Re: Still seeing "calcru: runtime went backwards" messages

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
> _at__at_ -761,14 +761,19 _at__at_
>  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);
> _at__at_ -779,16 +784,6 _at__at_
>  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);