CPU time accounting broken on 8-STABLE machine after a few hours of uptime

[Chip Camden]

Quoth Don Lewis on Monday, 27 September 2010:
> CPU time accounting is broken on one of my machines running 8-STABLE.  I
> ran a test with a simple program that just loops and consumes CPU time:
> 
> % time ./a.out
> 94.544u 0.000s 19:14.10 8.1%	62+2054k 0+0io 0pf+0w
> 
> The display in top shows the process with WCPU at 100%, but TIME
> increments very slowly.
> 
> Several hours after booting, I got a bunch of "calcru: runtime went
> backwards" messages, but they stopped right away and never appeared
> again.
> 
> Aug 23 13:40:07 scratch ntpd[1159]: ntpd 4.2.4p5-a (1)
> Aug 23 13:43:18 scratch ntpd[1160]: kernel time sync status change 2001
> Aug 23 18:05:57 scratch dbus-daemon: [system] Reloaded configuration
> Aug 23 18:06:16 scratch dbus-daemon: [system] Reloaded configuration
> Aug 23 18:12:40 scratch ntpd[1160]: time reset +18.059948 s
> [snip]
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 6836685136 usec to 5425839798 usec for pid 1526 (csh)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 4747 usec to 2403 usec for pid 1519 (csh)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 5265 usec to 2594 usec for pid 1494 (hald-addon-mouse-sy)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 7818 usec to 3734 usec for pid 1488 (console-kit-daemon)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 977 usec to 459 usec for pid 1480 (getty)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 958 usec to 450 usec for pid 1479 (getty)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 957 usec to 449 usec for pid 1478 (getty)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 952 usec to 447 usec for pid 1477 (getty)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 959 usec to 450 usec for pid 1476 (getty)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 975 usec to 458 usec for pid 1475 (getty)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 1026 usec to 482 usec for pid 1474 (getty)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 1333 usec to 626 usec for pid 1473 (getty)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 2469 usec to 1160 usec for pid 1440 (inetd)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 719 usec to 690 usec for pid 1402 (sshd)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 120486 usec to 56770 usec for pid 1360 (cupsd)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 6204 usec to 2914 usec for pid 1289 (dbus-daemon)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 179 usec to 84 usec for pid 1265 (moused)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 22156 usec to 10407 usec for pid 1041 (nfsd)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 1292 usec to 607 usec for pid 1032 (mountd)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 8801 usec to 4134 usec for pid 664 (devd)
> Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 19 usec to 9 usec for pid 9 (sctp_iterator)
> 
> 
> If I reboot and run the test again, the CPU time accounting seems to be
> working correctly.
> % time ./a.out
> 1144.226u 0.000s 19:06.62 99.7%	5+168k 0+0io 0pf+0w
> 
<snip>

I notice that before the calcru messages, ntpd reset the clock by
18 seconds -- that probably accounts for that.

I don't know if that has any connection to time(1) running slower -- but
perhaps ntpd is aggressively adjusting your clock?

-- 
Sterling (Chip) Camden    | sterling at camdensoftware.com | 2048D/3A978E4F
http://camdensoftware.com | http://chipstips.com        | http://chipsquips.com
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 488 bytes
Desc: not available
Url : http://lists.freebsd.org/pipermail/freebsd-stable/attachments/20100928/4f116348/attachment.pgp