Still seeing "calcru: runtime went backwards" messages
othermark
atkin901 at yahoo.com
Wed Mar 1 22:20:16 GMT 2006
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 at 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);
More information about the freebsd-current
mailing list