Date: Tue, 28 Sep 2010 07:39:55 -0700 From: Chip Camden <sterling@camdensoftware.com> To: stable@FreeBSD.org Subject: Re: CPU time accounting broken on 8-STABLE machine after a few hours of uptime Message-ID: <20100928143955.GA33940@libertas.local.camdensoftware.com> In-Reply-To: <201009280425.o8S4PA0d058131@gw.catspoiler.org> References: <201009280425.o8S4PA0d058131@gw.catspoiler.org>
next in thread | previous in thread | raw e-mail | index | archive | help
--GvXjxJ+pjyke8COw Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable 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: >=20 > % time ./a.out > 94.544u 0.000s 19:14.10 8.1% 62+2054k 0+0io 0pf+0w >=20 > The display in top shows the process with WCPU at 100%, but TIME > increments very slowly. >=20 > Several hours after booting, I got a bunch of "calcru: runtime went > backwards" messages, but they stopped right away and never appeared > again. >=20 > 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 68366= 85136 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 u= sec to 459 usec for pid 1480 (getty) > Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 958 u= sec to 450 usec for pid 1479 (getty) > Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 957 u= sec to 449 usec for pid 1478 (getty) > Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 952 u= sec to 447 usec for pid 1477 (getty) > Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 959 u= sec to 450 usec for pid 1476 (getty) > Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 975 u= sec 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 u= sec to 690 usec for pid 1402 (sshd) > Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 12048= 6 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 u= sec 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 us= ec to 9 usec for pid 9 (sctp_iterator) >=20 >=20 > 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 >=20 <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? --=20 Sterling (Chip) Camden | sterling@camdensoftware.com | 2048D/3A978E4F http://camdensoftware.com | http://chipstips.com | http://chipsquips= .com --GvXjxJ+pjyke8COw Content-Type: application/pgp-signature Content-Disposition: inline -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.10 (FreeBSD) iQEcBAEBAgAGBQJMof47AAoJEIpckszW26+R6rsIAKXPA1hFi5teoxzc4L0qqZaH zZN1N/WW0hmZrkxi4XjgSg9v5J/8AEIdI49+4VTZpjKzLQ1bSdVgLA+5IAw8MTpk dqHmlEtZftX7Gg52WQzwrGZVtuI0+jHR399o8rl0oOs36m0UK6wpx2KrbmvTjvnS Q9tTsQOwXlWr7/8F37Kr3fHNnLaRbaw1Ga6RwbUN9j+b3j4BdjftAg0j6zq19b0o IZqfySIj8ur4TkrS6HMSut6yDr1qBuOQ+ntEuLMAx+kUt6H+FmdsPrwC/wvtYxbn 7Q5zxjlpc0QJciinkjZ2ZQmWL/xZ/cPCxrL49vwTkkV70CFxpdUBSQuiyG+xF9k= =Kry2 -----END PGP SIGNATURE----- --GvXjxJ+pjyke8COw--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20100928143955.GA33940>