From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753431AbbEAKCd (ORCPT ); Fri, 1 May 2015 06:02:33 -0400 Received: from smtp-out-01.shaw.ca ([64.59.136.137]:52315 "EHLO smtp-out-01.shaw.ca" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750904AbbEAKCb (ORCPT ); Fri, 1 May 2015 06:02:31 -0400 X-Authority-Analysis: v=2.1 cv=HfbeNHw8 c=1 sm=1 tr=0 a=f/edn6q14DUxYFbwN4BeGQ==:117 a=f/edn6q14DUxYFbwN4BeGQ==:17 a=kj9zAlcOel0A:10 a=h1PgugrvaO0A:10 a=dUGbnWSUX0J5H0ozdTYA:9 a=5WGs31jig5tBDLFw:21 a=qLfBppqVms8k3ext:21 a=CjuIK1q_8ugA:10 Date: Fri, 1 May 2015 05:02:25 -0500 From: Trevor Cordes To: John Stultz Cc: lkml , Thomas Gleixner , Josh Boyer , One Thousand Gnomes Subject: Re: regression in ktime.h circa 3.16.0-rc5+ breaks lirc irsend, bad commit 166afb64511 Message-ID: <20150501050225.4c0ac17c@pog.tecnopolis.ca> In-Reply-To: References: <20150323165725.GA25008@pog.tecnopolis.ca> <20150429232721.59b89cb1@pog.tecnopolis.ca> X-Mailer: Claws Mail 3.11.1 (GTK+ 2.24.27; x86_64-redhat-linux-gnu) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit X-CMAE-Envelope: MS4wfMXcieo2eRN2XKydON4b0hvp6QU0OGWZ9GHlJ106Zm8RUnhgE8hhPY5wXhuGhRFxRdS8czwDiaV7zp8PEaDEnhfe7C08ch4hIBkvDdQXz6p2gzl+vxhGMg91zvnYXxm3GcLFey2DoiI6GSLg/THnKlg7bkzJnkNkcImEpizdi8/ZTmWJiV7Lp04zl9RHxRQBbl9O1F8fkuAkTvEne3x8/5+KwZLTDi3CRoFI0mVCvKheyHha4FiySGUppJp2G7mIpN6TunFLvtDZ6G6njAP44L7pgg/NeaoGjLlMZgPTpsMLvJyu+rM84Y87P68WeBlrhQ== Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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!