Messages in this thread | | | Date | Fri, 1 May 2015 05:02:25 -0500 | From | Trevor Cordes <> | Subject | Re: regression in ktime.h circa 3.16.0-rc5+ breaks lirc irsend, bad commit 166afb64511 |
| |
On 2015-04-30 John Stultz wrote: > >From your description it does seem like some sort of edge case > >problem > w/ the 32bit ktime_divns(), but I don't see it right off, and I agree > with Alan to do both calculations and print out warn when that > happens. > > There's also not a ton of users of that function, but ktime_us_delta() > is used in drivers/media/rc/ir-lirc-codec.c, which makes use of it in > ir_lirc_transmit_ir(). > > We should instrument that to see if its calculating negative deltas.
Thanks for looking at this! I didn't have the know-how to add the debug code myself (I was scared this fn might be called a zillion times in other kernel operations and overload the system with debug logging).
> I'll send you a debug patch to do the above.
Got the patch. Sorry for the delay (takes hours to compile using rpmbuild on this old P4 box).
I think I have "success" in terms of useful debug output (relevant lines only):
May 1 04:41:08 piles lircd: 'lirc' written to protocols file /sys/class/rc/rc0/protocols May 1 04:41:08 piles lircd-0.9.1a[978]: lircd(default) ready, using /var/run/lirc/lircd May 1 04:41:11 piles lircd-0.9.1a[978]: accepted new client on /var/run/lirc/lircd May 1 04:41:11 piles kernel: [ 55.265023] JDB: ktime_to_us: -20782699 -> divns 18446744073688768 != old method: -20783 May 1 04:44:00 piles lircd-0.9.1a[978]: removed client May 1 04:44:00 piles lircd-0.9.1a[978]: caught signal May 1 04:44:00 piles lircd: 'lirc' written to protocols file /sys/class/rc/rc0/protocols May 1 04:44:00 piles lircd-0.9.1a[1523]: lircd(default) ready, using /var/run/lirc/lircd May 1 04:45:03 piles lircd-0.9.1a[1523]: accepted new client on /var/run/lirc/lircd May 1 04:45:03 piles kernel: [ 287.445027] JDB: ktime_to_us: -20599906 -> divns 18446744073688951 != old method: -20600 May 1 04:45:37 piles lircd-0.9.1a[1523]: removed client May 1 04:45:37 piles lircd-0.9.1a[1523]: caught signal May 1 04:45:37 piles lircd: 'lirc' written to protocols file /sys/class/rc/rc0/protocols May 1 04:45:37 piles lircd-0.9.1a[1579]: lircd(default) ready, using /var/run/lirc/lircd May 1 04:45:40 piles lircd-0.9.1a[1579]: accepted new client on /var/run/lirc/lircd May 1 04:45:40 piles kernel: [ 324.209023] JDB: ktime_to_us: -20443355 -> divns 18446744073689108 != old method: -20444 May 1 04:46:12 piles lircd-0.9.1a[1579]: removed client May 1 04:46:12 piles lircd-0.9.1a[1579]: caught signal May 1 04:46:12 piles lircd: 'lirc' written to protocols file /sys/class/rc/rc0/protocols May 1 04:46:12 piles lircd-0.9.1a[1597]: lircd(default) ready, using /var/run/lirc/lircd May 1 04:46:12 piles lircd-0.9.1a[1597]: accepted new client on /var/run/lirc/lircd May 1 04:46:12 piles kernel: [ 356.838029] JDB: ktime_to_us: -20157485 -> divns 18446744073689394 != old method: -20158
The last 2-3 or 3 groups of output I could produce on demand by stopping mythbackend and running: systemctl restart lircd.service ; irsend SEND_ONCE dct700 info
Subsequent irsends don't trigger the bug, since (as I found out a while ago) by that point lircd is "hung", at least for a long while. Hey! Maybe lircd is then hung for 18446744073689394 us or ns :-) If this result is used as a delay timer, the negative would produce 0 delay, and the + number the "hang". I calculate that hang is 584 years? :-)
So it looks like maybe my theory wasn't so wacky: we're dealing with a caller passing negative numbers (or 32/64 weirdness). Very strange as it seems the caller *wants* (or is happy with) negative numbers!
Let me know if you need any more debugging/patch-tests. But give me 4+ hours between rpmbuilds (probably my responses will be 24-hr later).
Thanks a million!
| |