next »

[benjamin]

Version   1.2.2
      built on Thu Jan 8 22:30:24 EST 2009
      FreeBSD 7.0-RELEASE-p8 i386
Platform   pfSense
CPU Type   AMD Athlon(tm) 64 X2 Dual Core Processor 4600+ 


Been seeing strange errors showing up on my terminal screen. Searched a bit online and found that BSD doesn't always like AMD power saving modes. I run this in a VM under Xenserver 5.5, so I rebooted the whole box to turn off CPU powersaving / throttling. That made the issue go away for a while, but it resurfaced. I see 1.2.3 is out so I will upgrade to that, but what should I expect?
From the system logs:


Dec 12 16:57:59    kernel: calcru: runtime went backwards from 24766 usec to 22181 usec for pid 44047 (sh)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 30408 usec to 27234 usec for pid 44047 (sh)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 655 usec to 587 usec for pid 37931 (cron)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 87088 usec to 77999 usec for pid 0 (swapper)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 15088655387 usec to 13513975904 usec for pid 1 (init)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 380571 usec to 340854 usec for pid 1 (init)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 1677584369679 usec to 1502560982024 usec for pid 11 (idle: cpu1)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 1683837294850 usec to 1508158606929 usec for pid 12 (idle: cpu0)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 557311697 usec to 499150153 usec for pid 13 (swi1: net)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 2918200340 usec to 2616832446 usec for pid 14 (swi4: clock sio)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 52811259 usec to 47301863 usec for pid 2 (g_event)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 2309922908 usec to 2069002496 usec for pid 3 (g_up)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 3249949247 usec to 2910964477 usec for pid 4 (g_down)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 155974991 usec to 139700780 usec for pid 16 (yarrow)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 28791918 usec to 25787361 usec for pid 7 (thread taskq)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 10797 usec to 9671 usec for pid 17 (swi6: Giant taskq)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 115 usec to 103 usec for pid 18 (swi6: task queue)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 18369727865 usec to 16453069108 usec for pid 23 (swi5: +)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 1726884125 usec to 1546744414 usec for pid 25 (irq14: ata0)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 59336 usec to 53147 usec for pid 28 (usb0)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 234449 usec to 209981 usec for pid 31 (irq1: atkbd0)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 79 usec to 71 usec for pid 35 (sctp_iterator)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 15188627 usec to 13603828 usec for pid 36 (pfpurge)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 98330090 usec to 88068207 usec for pid 37 (pagedaemon)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 1357686 usec to 1215385 usec for pid 38 (vmdaemon)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 13043 usec to 11683 usec for pid 39 (pagezero)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 1042300 usec to 933584 usec for pid 40 (idlepoll)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 6271429 usec to 5617099 usec for pid 41 (bufdaemon)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 94507649 usec to 84647505 usec for pid 42 (syncer)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 88698262 usec to 79526143 usec for pid 43 (vnlru)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 7026239 usec to 6293154 usec for pid 44 (softdepflush)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 2739482 usec to 2453625 usec for pid 51 (md0)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 8510652 usec to 7622464 usec for pid 245 (dhclient)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 113741 usec to 101871 usec for pid 245 (dhclient)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 1580193 usec to 1415281 usec for pid 252 (sshd)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 6279 usec to 5624 usec for pid 252 (sshd)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 769810713 usec to 689473581 usec for pid 299 (dhclient)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 68956524 usec to 61762822 usec for pid 364 (tcpdump)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 52820641 usec to 47310245 usec for pid 365 (logger)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 253041 usec to 226633 usec for pid 488 (pftpx)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 100830231 usec to 90309171 usec for pid 530 (lighttpd)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 139408860 usec to 124859885 usec for pid 532 (php)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 27750 usec to 24853 usec for pid 532 (php)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 239074325 usec to 214124072 usec for pid 547 (php)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 29784 usec to 26676 usec for pid 547 (php)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 59471800 usec to 53265209 usec for pid 590 (dnsmasq)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 9138494 usec to 8185474 usec for pid 891 (dhcpd)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 218673364 usec to 195852193 usec for pid 922 (cron)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 7404228 usec to 6631565 usec for pid 922 (cron)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 423923250 usec to 379728412 usec for pid 6202 (minicron)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 2149362 usec to 1925293 usec for pid 6202 (minicron)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 383938346 usec to 343897164 usec for pid 4080 (miniupnpd)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 1912 usec to 1712 usec for pid 44045 (cron)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 725309071 usec to 649698059 usec for pid 44058 (check_reload_status)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 72868507 usec to 65267621 usec for pid 44058 (check_reload_status)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 12463 usec to 11162 usec for pid 42801 (login)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 5453 usec to 4884 usec for pid 42802 (sh)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 2742713 usec to 2456478 usec for pid 42803 (sh)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 21984 usec to 19690 usec for pid 42803 (sh)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 1693135016 usec to 1516779155 usec for pid 24248 (sh)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 109358825 usec to 97968146 usec for pid 24248 (sh)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 6559110 usec to 5875765 usec for pid 24373 (svscan)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 11635169 usec to 10422885 usec for pid 24374 (readproctitle)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 6550753 usec to 5868311 usec for pid 24516 (svscan)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 77382 usec to 69306 usec for pid 24517 (imspector)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 34856 usec to 31218 usec for pid 24517 (imspector)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 945 usec to 847 usec for pid 24518 (imspector)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 11643548 usec to 10430363 usec for pid 24519 (readproctitle)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 3953 usec to 3541 usec for pid 24520 (imspector)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 2613 usec to 2340 usec for pid 29061 (inetd)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 339800 usec to 311503 usec for pid 29187 (darkstat)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 4566 usec to 4090 usec for pid 29188 (darkstat)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 185219 usec to 168726 usec for pid 29573 (syslogd)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 5808975 usec to 5202739 usec for pid 40689 (php)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 3197116 usec to 2863459 usec for pid 40689 (php)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 403793 usec to 361652 usec for pid 43065 (php)
Dec 12 16:57:59    kernel: calcru: runtime went backwards from 218423 usec to 195628 usec for pid 43065 (php)

[benjamin]

No love. I updated, re-installed all the packages I had in use to clear up any incompatibilities that might have surfaced with the upgrade, rebooted. Everything seems fine for a few minutes then it spews out a bunch more...


Version      1.2.3-RELEASE
built on Sun Dec 6 23:38:21 EST 2009
FreeBSD 7.2-RELEASE-p5 i386
Platform    pfSense
CPU Type    AMD Athlon(tm) 64 X2 Dual Core Processor 4600+

[cmb]

That means your system's clock is running backwards, which is generally a BIOS bug. Make sure you're on the latest BIOS version, that usually fixes it. If it doesn't, disabling ACPI might.