"calcru: runtime went backwards" messages

[Jilles Tjoelker]

On Fri, Jun 11, 2010 at 12:35:05AM +0800, Jansen Gotis wrote:
> Hi, for the past couple of months since moving to RELENG_8 I've been
> receiving "calcru: runtime went backwards" messages on the console.

> My machine is a dual Pentium III 1.26GHz with an Intel SAI2 board.
> Disabling EIST is not an option in my BIOS, and I've tried disabling
> the ACPI timer as well as setting kern.timecounter.hardware=i8254.
> I've also tried disabling cpufreq in my kernel configuration.

> For what it's worth, I'm running base ntpd. I've also tried openntpd,
> but no dice.

> I did a binary search of the commit with which this started, and
> apparently it's svn r204546, a summary of which can be seen here:
> http://freshbsd.org/2010/03/02/01/56/55

> The calcru messages appear whether vesa is loaded as a module
> or compiled into the kernel.

> If anyone needs more information, I'll be happy to provide it.

> ===== snippet of /var/log/messages relating to calcru messages =====
> Jun 10 22:41:42 hobbes kernel: calcru: runtime went backwards from
> 3502 usec to 3297 usec for pid 1106 (mksh)
> Jun 10 22:41:42 hobbes kernel: calcru: runtime went backwards from
> 36785 usec to 35858 usec for pid 1114 (csh)
> Jun 10 22:41:42 hobbes kernel: calcru: runtime went backwards from
> 13438 usec to 12652 usec for pid 1113 (su)
> Jun 10 22:41:42 hobbes kernel: calcru: runtime went backwards from
> 14956 usec to 14081 usec for pid 1111 (mksh)
> Jun 10 22:41:42 hobbes kernel: calcru: runtime went backwards from
> 3323 usec to 3128 usec for pid 1111 (mksh)
> Jun 10 22:41:42 hobbes kernel: calcru: runtime went backwards from 610
> usec to 574 usec for pid 549 (devd)
> Jun 10 22:41:42 hobbes kernel: calcru: runtime went backwards from 517
> usec to 486 usec for pid 548 (dhclient)
> Jun 10 22:41:42 hobbes kernel: calcru: runtime went backwards from
> 1912 usec to 1800 usec for pid 532 (dhclient)
> Jun 10 22:41:42 hobbes kernel: calcru: runtime went backwards from
> 39738 usec to 37412 usec for pid 532 (dhclient)
> Jun 10 22:41:42 hobbes kernel: calcru: runtime went backwards from
> 3369010 usec to 3334846 usec for pid 1 (init)

This may well be a manifestation of a brokenness (which should not be
unknown) in how FreeBSD stores CPU time utilization. The time is
maintained in "CPU ticks" (CPU clock cycles), so if the clock frequency
changes, the values of existing processes will be wrong (a jump when
converted to seconds). When calcru detects this, it generates messages
like the above. If this analysis is right, the messages can be ignored,
but indicate that CPU time statistics may be inaccurate.

I suppose fairly arbitrary changes can cause the messages to appear or
disappear.

-- 
Jilles Tjoelker