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 | sterl...@camdensoftware.com | 2048D/3A978E4F http://camdensoftware.com | http://chipstips.com | http://chipsquips.com
pgpTvB0c4vm5i.pgp
Description: PGP signature
