From owner-freebsd-current@FreeBSD.ORG Wed Mar 1 22:20:16 2006 Return-Path: X-Original-To: freebsd-current@freebsd.org Delivered-To: freebsd-current@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 8434D16A420 for ; Wed, 1 Mar 2006 22:20:16 +0000 (GMT) (envelope-from freebsd-current@m.gmane.org) Received: from ciao.gmane.org (main.gmane.org [80.91.229.2]) by mx1.FreeBSD.org (Postfix) with ESMTP id CC10A43D66 for ; Wed, 1 Mar 2006 22:20:15 +0000 (GMT) (envelope-from freebsd-current@m.gmane.org) Received: from list by ciao.gmane.org with local (Exim 4.43) id 1FEZfZ-0001Pe-FN for freebsd-current@freebsd.org; Wed, 01 Mar 2006 23:19:41 +0100 Received: from gw205.f5.com ([205.229.151.151]) by main.gmane.org with esmtp (Gmexim 0.1 (Debian)) id 1AlnuQ-0007hv-00 for ; Wed, 01 Mar 2006 23:19:41 +0100 Received: from atkin901 by gw205.f5.com with local (Gmexim 0.1 (Debian)) id 1AlnuQ-0007hv-00 for ; Wed, 01 Mar 2006 23:19:41 +0100 X-Injected-Via-Gmane: http://gmane.org/ To: freebsd-current@freebsd.org From: othermark Date: Wed, 01 Mar 2006 14:18:47 -0800 Lines: 99 Message-ID: References: <4405E745.9040604@rogers.com> <200603011357.12175.jhb@freebsd.org> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7Bit X-Complaints-To: usenet@sea.gmane.org X-Gmane-NNTP-Posting-Host: gw205.f5.com User-Agent: KNode/0.10.1 Sender: news Subject: Re: Still seeing "calcru: runtime went backwards" messages X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 01 Mar 2006 22:20:16 -0000 John Baldwin wrote: > On Wednesday 01 March 2006 13:26, Mike Jakubik wrote: >> FYI, I just did a fresh cvsup and buildworld yesterday night, and i am >> still getting the clacru messages: >> >> Mar 1 02:41:37 fbsd kernel: calcru: runtime went backwards from 32465 >> usec to 32464 usec for pid 490 (sh) >> Mar 1 02:41:37 fbsd kernel: u 0:0/0 s 1:32465/32464 i 0:0/0 >> Mar 1 02:41:37 fbsd kernel: calcru: runtime went backwards from 17198 >> usec to 17197 usec for pid 318 (devd) >> Mar 1 02:41:37 fbsd kernel: u 0:0/0 s 2:17198/17197 i 0:0/0 >> Mar 1 02:45:45 fbsd kernel: calcru: runtime went backwards from 3403872 >> usec to 3403870 usec for pid 722 (perl5.8.8) >> Mar 1 02:45:45 fbsd kernel: u 367:2852102/2852101 s 71:551769/551768 i >> 0:1/1 >> Mar 1 02:45:45 fbsd kernel: calcru: runtime went backwards from 5135265 >> usec to 5135263 usec for pid 1 (init) >> Mar 1 02:45:45 fbsd kernel: u 298:2383658/2383657 s 344:2751606/2751605 >> i 0:1/1 > > Try this fix for one. It fixes the case that once time goes backward once > we keep using the last known time rather than using the new shorter time: > > Index: kern_resource.c > =================================================================== > RCS file: /usr/cvs/src/sys/kern/kern_resource.c,v > retrieving revision 1.156 > diff -u -r1.156 kern_resource.c > --- kern_resource.c 22 Feb 2006 16:58:48 -0000 1.156 > +++ kern_resource.c 22 Feb 2006 17:00:38 -0000 > @@ -761,14 +761,19 @@ > ut = ruxp->rux_uticks; > st = ruxp->rux_sticks; > it = ruxp->rux_iticks; > - tu = ruxp->rux_runtime; > - tu = cputick2usec(tu); > tt = ut + st + it; > if (tt == 0) { > st = 1; > tt = 1; > } > + tu = cputick2usec(ruxp->rux_runtime); > ptu = ruxp->rux_uu + ruxp->rux_su + ruxp->rux_iu; > + if (tu < ptu) { > + printf( > +"calcru: runtime went backwards from %ju usec to %ju usec for pid %d > (%s)\n", > + (uintmax_t)ptu, (uintmax_t)tu, p->p_pid, p->p_comm); > + tu = ptu; > + } > if ((int64_t)tu < 0) { > printf("calcru: negative runtime of %jd usec for pid %d (%s)\n", > (intmax_t)tu, p->p_pid, p->p_comm); > @@ -779,16 +784,6 @@ > uu = (tu * ut) / tt; > su = (tu * st) / tt; > iu = tu - uu - su; > - if (tu < ptu) { > - printf( > -"calcru: runtime went backwards from %ju usec to %ju usec for pid %d > (%s)\n", > - (uintmax_t)ptu, (uintmax_t)tu, p->p_pid, p->p_comm); > - printf("u %ju:%ju/%ju s %ju:%ju/%ju i %ju:%ju/%ju\n", > - (uintmax_t)ut, (uintmax_t)ruxp->rux_uu, uu, > - (uintmax_t)st, (uintmax_t)ruxp->rux_su, su, > - (uintmax_t)it, (uintmax_t)ruxp->rux_iu, iu); > - tu = ptu; > - } > #if 0 > /* Enforce monotonicity. */ > if (uu < ruxp->rux_uu || su < ruxp->rux_su || iu < ruxp->rux_iu) { > I've been seeing them as well. This patch actually makes them more prevalent. I seem to get related bad behavior seemingly related to these messages with em(4) (when accessing nfs heavily): [root@moby ~]$ dmesg -a |grep calcru: |wc -l 208 [...] Mar 1 14:08:08 moby kernel: calcru: runtime went backwards from 5776 usec to 5775 usec for pid 19301 (pflogd) Mar 1 14:08:08 moby kernel: calcru: runtime went backwards from 21916 usec to 21915 usec for pid 18 (swi5: +) Mar 1 14:09:52 moby kernel: em0: watchdog timeout -- resetting Mar 1 14:09:52 moby kernel: devnet: link state changed to DOWN Mar 1 14:09:55 moby kernel: devnet: link state changed to UP Mar 1 14:11:43 moby kernel: nfs/tcp clnt: Error 60 reading socket, tearing down TCP connection Mar 1 14:11:45 moby kernel: nfs server linuxnfs3:/vol/vol0: not responding Mar 1 14:11:48 moby last message repeated 4 times Mar 1 14:11:55 moby ntpd[19695]: kernel time sync enabled 2001 -- othermark atkin901 at nospam dot yahoo dot com (!wired)?(coffee++):(wired);