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

2010-10-01 Thread Don Lewis 
On 30 Sep, Don Lewis wrote:

 The silent reboots that I was seeing with WITNESS go away if I add
 WITNESS_SKIPSPIN.  Witness doesn't complain about anything.

I've tracked down the the silent reboot problem.  It happens when a
userland sysctl call gets down into calcru1(), which tries to print a
calcu: .. message.  Eventually sc_puts() wants to grab a spin lock,
which causes a call to witness, which detects a lock order reversal.
This recurses into printf(), which dives back into the console code and
eventually triggers a panic.

I'm still gathering the details on this and I see what I can come up
with for a fix.

 I tested -CURRENT and !SMP seems to work ok.  One difference in terms of
 hardware between the two tests is that I'm using a SATA drive when
 testing -STABLE and a SCSI drive when testing -CURRENT.

I'm not able to trigger the problem with -CURRENT when it is running on
a SCSI drive, but I do see the freezes, long ping RTTs, and ntp insanity
when running a !SMP -CURRENT kernel on my SATA drive with an 8.1-STABLE
world.

___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-30 Thread Andriy Gapon 
on 30/09/2010 02:27 Don Lewis said the following:
 On 29 Sep, Andriy Gapon wrote:
 on 29/09/2010 11:56 Don Lewis said the following:
 I'm using the same kernel config as the one on a slower !SMP box which
 I'm trying to squeeze as much performance out of as possible.  My kernel
 config file contains these statements:
 nooptions   SMP
 nodeviceapic

 Testing with an SMP kernel is on my TODO list.

 SMP or not, it's really weird to see apic disabled nowadays.
 
 I tried enabling apic and got worse results.  I saw ping RTTs as high as
 67 seconds.  Here's the timer info with apic enabled:

I didn't expect anything to change in this output with APIC enabled.

 # sysctl kern.timecounter
 kern.timecounter.tick: 1
 kern.timecounter.choice: TSC(800) ACPI-fast(1000) i8254(0) dummy(-100)
 kern.timecounter.hardware: ACPI-fast
 kern.timecounter.stepwarnings: 0
 kern.timecounter.tc.i8254.mask: 65535
 kern.timecounter.tc.i8254.counter: 53633
 kern.timecounter.tc.i8254.frequency: 1193182
 kern.timecounter.tc.i8254.quality: 0
 kern.timecounter.tc.ACPI-fast.mask: 16777215
 kern.timecounter.tc.ACPI-fast.counter: 7988816
 kern.timecounter.tc.ACPI-fast.frequency: 3579545
 kern.timecounter.tc.ACPI-fast.quality: 1000
 kern.timecounter.tc.TSC.mask: 4294967295
 kern.timecounter.tc.TSC.counter: 1341917999
 kern.timecounter.tc.TSC.frequency: 2500014018
 kern.timecounter.tc.TSC.quality: 800
 kern.timecounter.invariant_tsc: 0
 
 Here's the verbose boot info with apic:
 http://people.freebsd.org/~truckman/AN-M2_HD-8.1-STABLE-apic-verbose.txt

vmstat -i ?

 I've also experimented with SMP as well as SCHED_4BSD (all previous
 testing was with !SMP and SCHED_ULE).  I still see occasional problems
 with SCHED_4BSD and !SMP, but so far I have not seen any problems with
 SCHED_ULE and SMP.

Good!

 I did manage to catch the problem with lock profiling enabled:
 http://people.freebsd.org/~truckman/AN-M2_HD-8.1-STABLE_lock_profile_freeze.txt
 I'm currently testing SMP some more to verify if it really avoids this
 problem.

OK.

-- 
Andriy Gapon
___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-30 Thread Don Lewis 
On 30 Sep, Andriy Gapon wrote:
 on 30/09/2010 02:27 Don Lewis said the following:

 vmstat -i ?

I didn't see anything odd in the vmstat -i output that I posted to the list
earlier.  It looked more or less normal as the ntp offset suddenly went
insane.
 
 I did manage to catch the problem with lock profiling enabled:
 http://people.freebsd.org/~truckman/AN-M2_HD-8.1-STABLE_lock_profile_freeze.txt
 I'm currently testing SMP some more to verify if it really avoids this
 problem.
 
 OK.

I wasn't able to cause SMP on stable to break.

The silent reboots that I was seeing with WITNESS go away if I add
WITNESS_SKIPSPIN.  Witness doesn't complain about anything.

I tested -CURRENT and !SMP seems to work ok.  One difference in terms of
hardware between the two tests is that I'm using a SATA drive when
testing -STABLE and a SCSI drive when testing -CURRENT.

At this point, I think the biggest clues are going to be in the lock
profile results.

___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-30 Thread Don Lewis 
On 30 Sep, Andriy Gapon wrote:
 on 30/09/2010 02:27 Don Lewis said the following:

 I tried enabling apic and got worse results.  I saw ping RTTs as high as
 67 seconds.  Here's the timer info with apic enabled:
[snip]
 Here's the verbose boot info with apic:
 http://people.freebsd.org/~truckman/AN-M2_HD-8.1-STABLE-apic-verbose.txt
 
 vmstat -i ?

Here's the vmstat -i output at the time the machine starts experiencing
freezes and ntp goes insane:

Thu Sep 30 11:38:57 PDT 2010
interrupt  total   rate
irq1: atkbd0   6  0
irq9: acpi0   10  0
irq12: psm0   18  0
irq14: ata0 2845  1
irq17: ahc0  310  0
irq19: fwohci0 1  0
irq22: ehci0+  74628 40
cpu0: timer  3676399   1999
irq256: nfe03915  2
Total3758132   2043
 remote   refid  st t when poll reach   delay   offset  jitter
==
*gw.catspoiler.o .GPS.1 u  129  128  3770.185   -0.307   0.020

Thu Sep 30 11:39:59 PDT 2010
interrupt  total   rate
irq1: atkbd0   6  0
irq9: acpi0   10  0
irq12: psm0   18  0
irq14: ata0 2935  1
irq17: ahc0  310  0
irq19: fwohci0 1  0
irq22: ehci0+  78954 41
cpu0: timer  3796447   1998
irq256: nfe04090  2
Total3882771   2043
 remote   refid  st t when poll reach   delay   offset  jitter
==
*gw.catspoiler.o .GPS.1 u   61  128  3770.185   -0.307   0.023

Thu Sep 30 11:40:59 PDT 2010
interrupt  total   rate
irq1: atkbd0   6  0
irq9: acpi0   10  0
irq12: psm0   18  0
irq14: ata0 3025  1
irq17: ahc0  310  0
irq19: fwohci0 1  0
irq22: ehci0+  85038 43
cpu0: timer  3916483   1998
irq256: nfe04247  2
Total4009138   2045
 remote   refid  st t when poll reach   delay   offset  jitter
==
*gw.catspoiler.o .GPS.1 u  121  128  3770.185   -0.307   0.023

Thu Sep 30 11:41:59 PDT 2010
interrupt  total   rate
irq1: atkbd0   6  0
irq9: acpi0   10  0
irq12: psm0   18  0
irq14: ata0 3115  1
irq17: ahc0  310  0
irq19: fwohci0 1  0
irq22: ehci0+  89099 44
cpu0: timer  4036529   1998
irq256: nfe04384  2
Total4133472   2046
 remote   refid  st t when poll reach   delay   offset  jitter
==
*gw.catspoiler.o .GPS.1 u   54  128  3770.185   -0.307 43008.9

Thu Sep 30 11:42:59 PDT 2010
interrupt  total   rate
irq1: atkbd0   6  0
irq9: acpi0   11  0
irq12: psm0   18  0
irq14: ata0 3205  1
irq17: ahc0  310  0
irq19: fwohci0 1  0
irq22: ehci0+  92111 44
cpu0: timer  4156575   1998
irq256: nfe04421  2
Total4256658   2046
 remote   refid  st t when poll reach   delay   offset  jitter
==
*gw.catspoiler.o .GPS.1 u  114  128  3770.185   -0.307 43008.9

Thu Sep 30 11:43:59 PDT 2010
interrupt  total   rate
irq1: atkbd0   6  0
irq9: acpi0   12  0
irq12: psm0   18  0
irq14: ata0 3295  1
irq17: ahc0  310  0
irq19:

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

2010-09-29 Thread Jeremy Chadwick 
On Tue, Sep 28, 2010 at 10:31:27PM -0700, Don Lewis wrote:
 On 28 Sep, Don Lewis wrote:
 
  Looking at the timestamps of things and comparing to my logs, I
  discovered that the last instance of ntp instability happened when I was
  running make index in /usr/ports.  I tried it again with entertaining
  results.  After a while, the machine became unresponsive.  I was logged
  in over ssh and it stopped echoing keystrokes.  In parallel I was
  running a script that echoed the date, the results of vmstat -i, and
  the results of ntpq -c pe.  The latter showed jitter and offset going
  insane.  Eventually make index finished and the machine was responsive
  again, but the time was way off and ntpd croaked because the necessary
  time correction was too large.  Nothing else anomalous showed up in the
  logs.  Hmn, about half an hour after ntpd died I started my CPU time
  accounting test and two minutes into that test I got a spew of calcru
  messages ...
 
 I tried this experiment again using a kernel with WITNESS and
 DEBUG_VFS_LOCKS compiled in, and pinging this machine from another.
 Things look normal for a while, then the ping times get huge for a while
 and then recover.
 
 64 bytes from 192.168.101.3: icmp_seq=1169 ttl=64 time=0.135 ms
 64 bytes from 192.168.101.3: icmp_seq=1170 ttl=64 time=0.141 ms
 64 bytes from 192.168.101.3: icmp_seq=1171 ttl=64 time=0.130 ms
 64 bytes from 192.168.101.3: icmp_seq=1172 ttl=64 time=0.131 ms
 64 bytes from 192.168.101.3: icmp_seq=1173 ttl=64 time=0.128 ms
 64 bytes from 192.168.101.3: icmp_seq=1174 ttl=64 time=38232.140 ms
 64 bytes from 192.168.101.3: icmp_seq=1175 ttl=64 time=37231.309 ms
 64 bytes from 192.168.101.3: icmp_seq=1176 ttl=64 time=36230.470 ms
 64 bytes from 192.168.101.3: icmp_seq=1177 ttl=64 time=35229.632 ms
 64 bytes from 192.168.101.3: icmp_seq=1178 ttl=64 time=34228.791 ms
 64 bytes from 192.168.101.3: icmp_seq=1179 ttl=64 time=33227.953 ms
 64 bytes from 192.168.101.3: icmp_seq=1180 ttl=64 time=32227.091 ms
 64 bytes from 192.168.101.3: icmp_seq=1181 ttl=64 time=31226.262 ms
 64 bytes from 192.168.101.3: icmp_seq=1182 ttl=64 time=30225.425 ms
 64 bytes from 192.168.101.3: icmp_seq=1183 ttl=64 time=29224.597 ms
 64 bytes from 192.168.101.3: icmp_seq=1184 ttl=64 time=28223.757 ms
 64 bytes from 192.168.101.3: icmp_seq=1185 ttl=64 time=27222.918 ms
 64 bytes from 192.168.101.3: icmp_seq=1186 ttl=64 time=26222.086 ms
 64 bytes from 192.168.101.3: icmp_seq=1187 ttl=64 time=25221.164 ms
 64 bytes from 192.168.101.3: icmp_seq=1188 ttl=64 time=24220.407 ms
 64 bytes from 192.168.101.3: icmp_seq=1189 ttl=64 time=23219.575 ms
 64 bytes from 192.168.101.3: icmp_seq=1190 ttl=64 time=22218.737 ms
 64 bytes from 192.168.101.3: icmp_seq=1191 ttl=64 time=21217.905 ms
 64 bytes from 192.168.101.3: icmp_seq=1192 ttl=64 time=20217.066 ms
 64 bytes from 192.168.101.3: icmp_seq=1193 ttl=64 time=19216.228 ms
 64 bytes from 192.168.101.3: icmp_seq=1194 ttl=64 time=18215.333 ms
 64 bytes from 192.168.101.3: icmp_seq=1195 ttl=64 time=17214.503 ms
 64 bytes from 192.168.101.3: icmp_seq=1196 ttl=64 time=16213.720 ms
 64 bytes from 192.168.101.3: icmp_seq=1197 ttl=64 time=15210.912 ms
 64 bytes from 192.168.101.3: icmp_seq=1198 ttl=64 time=14210.044 ms
 64 bytes from 192.168.101.3: icmp_seq=1199 ttl=64 time=13209.194 ms
 64 bytes from 192.168.101.3: icmp_seq=1200 ttl=64 time=12208.376 ms
 64 bytes from 192.168.101.3: icmp_seq=1201 ttl=64 time=11207.536 ms
 64 bytes from 192.168.101.3: icmp_seq=1202 ttl=64 time=10206.694 ms
 64 bytes from 192.168.101.3: icmp_seq=1203 ttl=64 time=9205.816 ms
 64 bytes from 192.168.101.3: icmp_seq=1204 ttl=64 time=8205.014 ms
 64 bytes from 192.168.101.3: icmp_seq=1205 ttl=64 time=7204.186 ms
 64 bytes from 192.168.101.3: icmp_seq=1206 ttl=64 time=6203.294 ms
 64 bytes from 192.168.101.3: icmp_seq=1207 ttl=64 time=5202.510 ms
 64 bytes from 192.168.101.3: icmp_seq=1208 ttl=64 time=4201.677 ms
 64 bytes from 192.168.101.3: icmp_seq=1209 ttl=64 time=3200.851 ms
 64 bytes from 192.168.101.3: icmp_seq=1210 ttl=64 time=2200.013 ms
 64 bytes from 192.168.101.3: icmp_seq=1211 ttl=64 time=1199.100 ms
 64 bytes from 192.168.101.3: icmp_seq=1212 ttl=64 time=198.331 ms
 64 bytes from 192.168.101.3: icmp_seq=1213 ttl=64 time=0.129 ms
 64 bytes from 192.168.101.3: icmp_seq=1214 ttl=64 time=58223.470 ms
 64 bytes from 192.168.101.3: icmp_seq=1215 ttl=64 time=57222.637 ms
 64 bytes from 192.168.101.3: icmp_seq=1216 ttl=64 time=56221.800 ms
 64 bytes from 192.168.101.3: icmp_seq=1217 ttl=64 time=55220.960 ms
 64 bytes from 192.168.101.3: icmp_seq=1218 ttl=64 time=54220.116 ms
 64 bytes from 192.168.101.3: icmp_seq=1219 ttl=64 time=53219.282 ms
 64 bytes from 192.168.101.3: icmp_seq=1220 ttl=64 time=52218.444 ms
 64 bytes from 192.168.101.3: icmp_seq=1221 ttl=64 time=51217.618 ms
 64 bytes from 192.168.101.3: icmp_seq=1222 ttl=64 time=50216.778 ms
 64 bytes from 192.168.101.3: icmp_seq=1223 ttl=64 time=49215.932 ms
 64 bytes from 192.168.101.3: icmp_seq=1224

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

2010-09-29 Thread Don Lewis 
On 29 Sep, Jeremy Chadwick wrote:

 Given all the information here, in addition to the other portion of the
 thread (indicating ntpd reports extreme offset between the system clock
 and its stratum 1 source), I would say the motherboard is faulty or
 there is a system device which is behaving badly (possibly something
 pertaining to interrupts, but I don't know how to debug this on a low
 level).

Possible, but I haven't run into any problems running -CURRENT on this
box with an SMP kernel.

 Can you boot verbosely and provide all of the output here or somewhere
 on the web?

http://people.freebsd.org/~truckman/AN-M2_HD-8.1-STABLE-verbose.txt

 If possible, I would start by replacing the mainboard.  The board looks
 to be a consumer-level board (I see an nfe(4) controller, for example).

It's an Abit AN-M2 HD.  The RAM is ECC.  I haven't seen any machine
check errors in the logs.  I'll run prime95 as soon as I have a chance.

___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-29 Thread Jeremy Chadwick 
On Wed, Sep 29, 2010 at 12:39:49AM -0700, Don Lewis wrote:
 On 29 Sep, Jeremy Chadwick wrote:
 
  Given all the information here, in addition to the other portion of the
  thread (indicating ntpd reports extreme offset between the system clock
  and its stratum 1 source), I would say the motherboard is faulty or
  there is a system device which is behaving badly (possibly something
  pertaining to interrupts, but I don't know how to debug this on a low
  level).
 
 Possible, but I haven't run into any problems running -CURRENT on this
 box with an SMP kernel.
 
  Can you boot verbosely and provide all of the output here or somewhere
  on the web?
 
 http://people.freebsd.org/~truckman/AN-M2_HD-8.1-STABLE-verbose.txt
 
  If possible, I would start by replacing the mainboard.  The board looks
  to be a consumer-level board (I see an nfe(4) controller, for example).
 
 It's an Abit AN-M2 HD.  The RAM is ECC.  I haven't seen any machine
 check errors in the logs.  I'll run prime95 as soon as I have a chance.

Thanks for the verbose boot.  Since it works on -CURRENT, can you
provide a verbose boot from that as well?  Possibly someone made some
changes between RELENG_8 and HEAD which fixed an issue, which could be
MFC'd.

-- 
| Jeremy Chadwick   j...@parodius.com |
| Parodius Networking   http://www.parodius.com/ |
| UNIX Systems Administrator  Mountain View, CA, USA |
| Making life hard for others since 1977.  PGP: 4BD6C0CB |

___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-29 Thread Don Lewis 
On 29 Sep, Jeremy Chadwick wrote:
 On Wed, Sep 29, 2010 at 12:39:49AM -0700, Don Lewis wrote:
 On 29 Sep, Jeremy Chadwick wrote:
 
  Given all the information here, in addition to the other portion of the
  thread (indicating ntpd reports extreme offset between the system clock
  and its stratum 1 source), I would say the motherboard is faulty or
  there is a system device which is behaving badly (possibly something
  pertaining to interrupts, but I don't know how to debug this on a low
  level).
 
 Possible, but I haven't run into any problems running -CURRENT on this
 box with an SMP kernel.
 
  Can you boot verbosely and provide all of the output here or somewhere
  on the web?
 
 http://people.freebsd.org/~truckman/AN-M2_HD-8.1-STABLE-verbose.txt
 
  If possible, I would start by replacing the mainboard.  The board looks
  to be a consumer-level board (I see an nfe(4) controller, for example).
 
 It's an Abit AN-M2 HD.  The RAM is ECC.  I haven't seen any machine
 check errors in the logs.  I'll run prime95 as soon as I have a chance.
 
 Thanks for the verbose boot.  Since it works on -CURRENT, can you
 provide a verbose boot from that as well?  Possibly someone made some
 changes between RELENG_8 and HEAD which fixed an issue, which could be
 MFC'd.

Even when I saw the wierd ntp stepping problem and the calcru messages,
the system was still stable enough to build hundreds of ports.  In the
most recent case, I built 800+ ports over several days without any other
hiccups.

It could also be a difference between SMP and !SMP.  I just found a bug
that causes an immediate panic if lock profiling is enabled on a !SMP
kernel.  This bug also exists in -CURRENT.  Here's the patch:

Index: sys/sys/mutex.h
===
RCS file: /home/ncvs/src/sys/sys/mutex.h,v
retrieving revision 1.105.2.1
diff -u -r1.105.2.1 mutex.h
--- sys/sys/mutex.h 3 Aug 2009 08:13:06 -   1.105.2.1
+++ sys/sys/mutex.h 29 Sep 2010 06:58:52 -
@@ -251,8 +251,11 @@
 #define _rel_spin_lock(mp) do {
\
if (mtx_recursed((mp))) \
(mp)-mtx_recurse--;\
-   else\
+   else {  \
(mp)-mtx_lock = MTX_UNOWNED;   \
+   LOCKSTAT_PROFILE_RELEASE_LOCK(LS_MTX_SPIN_UNLOCK_RELEASE, \
+   mp);\
+   }   \
spinlock_exit();\
 } while (0)
 #endif /* SMP */


After applying the above patch, I enabled lock profiling and got the
following results when I ran make index:
http://people.freebsd.org/~truckman/AN-M2_HD-8.1-STABLE_lock_profile.txt

I didn't see anything strange happening this time.  I don't know if I
got lucky, or the change in kernel options fixed the bug.

___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-29 Thread Andriy Gapon 
on 29/09/2010 00:11 Don Lewis said the following:
 On 28 Sep, Don Lewis wrote:
 
 
 % vmstat -i
 interrupt  total   rate
 irq0: clk   60683442   1000
 irq1: atkbd0   6  0
 irq8: rtc7765537127
 irq9: acpi0   13  0
 irq10: ohci0 ehci1+ 10275064169
 irq11: fwohci0 ahc+   132133  2
 irq12: psm0   21  0
 irq14: ata090982  1
 irq15: nfe0 ata1   18363  0

 I'm not sure why I'm getting USB interrupts.  There aren't any USB
 devices plugged into this machine.
 
 Answer: irq 10 is also shared by vgapci0 and atapci1.

Just curious why Local APIC timer isn't being used for hardclock on your system.

-- 
Andriy Gapon
___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-29 Thread Don Lewis 
On 29 Sep, Andriy Gapon wrote:
 on 29/09/2010 00:11 Don Lewis said the following:
 On 28 Sep, Don Lewis wrote:
 
 
 % vmstat -i
 interrupt  total   rate
 irq0: clk   60683442   1000
 irq1: atkbd0   6  0
 irq8: rtc7765537127
 irq9: acpi0   13  0
 irq10: ohci0 ehci1+ 10275064169
 irq11: fwohci0 ahc+   132133  2
 irq12: psm0   21  0
 irq14: ata090982  1
 irq15: nfe0 ata1   18363  0

 I'm not sure why I'm getting USB interrupts.  There aren't any USB
 devices plugged into this machine.
 
 Answer: irq 10 is also shared by vgapci0 and atapci1.
 
 Just curious why Local APIC timer isn't being used for hardclock on your 
 system.

I'm using the same kernel config as the one on a slower !SMP box which
I'm trying to squeeze as much performance out of as possible.  My kernel
config file contains these statements:
nooptions   SMP
nodeviceapic

Testing with an SMP kernel is on my TODO list.


___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-29 Thread Andriy Gapon 
on 29/09/2010 11:56 Don Lewis said the following:
 I'm using the same kernel config as the one on a slower !SMP box which
 I'm trying to squeeze as much performance out of as possible.  My kernel
 config file contains these statements:
   nooptions   SMP
   nodeviceapic
 
 Testing with an SMP kernel is on my TODO list.

SMP or not, it's really weird to see apic disabled nowadays.

-- 
Andriy Gapon
___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-29 Thread Don Lewis 
On 29 Sep, Andriy Gapon wrote:
 on 29/09/2010 11:56 Don Lewis said the following:
 I'm using the same kernel config as the one on a slower !SMP box which
 I'm trying to squeeze as much performance out of as possible.  My kernel
 config file contains these statements:
  nooptions   SMP
  nodeviceapic
 
 Testing with an SMP kernel is on my TODO list.
 
 SMP or not, it's really weird to see apic disabled nowadays.

I tried enabling apic and got worse results.  I saw ping RTTs as high as
67 seconds.  Here's the timer info with apic enabled:

# sysctl kern.timecounter
kern.timecounter.tick: 1
kern.timecounter.choice: TSC(800) ACPI-fast(1000) i8254(0) dummy(-100)
kern.timecounter.hardware: ACPI-fast
kern.timecounter.stepwarnings: 0
kern.timecounter.tc.i8254.mask: 65535
kern.timecounter.tc.i8254.counter: 53633
kern.timecounter.tc.i8254.frequency: 1193182
kern.timecounter.tc.i8254.quality: 0
kern.timecounter.tc.ACPI-fast.mask: 16777215
kern.timecounter.tc.ACPI-fast.counter: 7988816
kern.timecounter.tc.ACPI-fast.frequency: 3579545
kern.timecounter.tc.ACPI-fast.quality: 1000
kern.timecounter.tc.TSC.mask: 4294967295
kern.timecounter.tc.TSC.counter: 1341917999
kern.timecounter.tc.TSC.frequency: 2500014018
kern.timecounter.tc.TSC.quality: 800
kern.timecounter.invariant_tsc: 0

Here's the verbose boot info with apic:
http://people.freebsd.org/~truckman/AN-M2_HD-8.1-STABLE-apic-verbose.txt


I've also experimented with SMP as well as SCHED_4BSD (all previous
testing was with !SMP and SCHED_ULE).  I still see occasional problems
with SCHED_4BSD and !SMP, but so far I have not seen any problems with
SCHED_ULE and SMP.

I did manage to catch the problem with lock profiling enabled:
http://people.freebsd.org/~truckman/AN-M2_HD-8.1-STABLE_lock_profile_freeze.txt


I'm currently testing SMP some more to verify if it really avoids this
problem.

___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-28 Thread 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| sterl...@camdensoftware.com | 2048D/3A978E4F
http://camdensoftware.com | http://chipstips.com| http://chipsquips.com


pgpTvB0c4vm5i.pgp
Description: PGP signature

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

2010-09-28 Thread Don Lewis 
On 28 Sep, Chip Camden wrote:
 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.

Interesting observation.  Since this happened so early in the log, I
thought that this time change was the initial time change after boot,
but taking a closer look, the time change occurred about 4 1/2 hours
after boot.  The calcru messages occured another 5 1/2 hours after that.

I also just noticed that this log info was from the August 23rd kernel,
before I noticed the CPU time accounting problem, and not the latest
occurance.  Here's the latest log info:

Sep 23 16:33:50 scratch ntpd[1144]: ntpd 4.2.4p5-a (1)
Sep 23 16:37:03 scratch ntpd[1145]: kernel time sync status change 2001
Sep 23 17:43:47 scratch ntpd[1145]: time reset +276.133928 s
Sep 23 17:43:47 scratch ntpd[1145]: kernel time sync status change 6001
Sep 23 17:47:15 scratch ntpd[1145]: kernel time sync status change 2001
Sep 23 19:02:48 scratch ntpd[1145]: time reset +291.507262 s
Sep 23 19:02:48 scratch ntpd[1145]: kernel time sync status change 6001
Sep 23 19:06:37 scratch ntpd[1145]: kernel time sync status change 2001
Sep 24 00:03:36 scratch kernel: calcru: runtime went backwards from 1120690857 u
sec to 367348485 usec for pid 1518 (csh)
Sep 24 00:03:36 scratch kernel: calcru: runtime went backwards from 5403 usec to
 466 usec for pid 1477 (hald-addon-mouse-sy)
Sep 24 00:03:36 scratch kernel: calcru: runtime went backwards from 7511 usec to
 1502 usec for pid 1472 (hald-runner)
Sep 24 00:03:36

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

2010-09-28 Thread Jeremy Chadwick 
On Tue, Sep 28, 2010 at 10:15:34AM -0700, Don Lewis wrote:
 My time source is another FreeBSD box with a GPS receiver on my LAN.  My
 other client machine isn't seeing these time jumps.  The only messages
 from ntp in its log from this period are these:
 
 Sep 23 04:12:23 mousie ntpd[]: kernel time sync status change 6001
 Sep 23 04:29:29 mousie ntpd[]: kernel time sync status change 2001
 Sep 24 03:55:24 mousie ntpd[]: kernel time sync status change 6001
 Sep 24 04:12:28 mousie ntpd[]: kernel time sync status change 2001

I'm speaking purely about ntpd below this point -- almost certainly a
separate problem/issue, but I'll explain it anyway.  I'm not under the
impression that the calcru messages indicate RTC clock drift, but I'd
need someone like John Baldwin to validate my statement.

Back to ntpd: you can addressing the above messages by adding maxpoll
9 to your server lines in ntp.conf.  The comment we use in our
ntp.conf that documents the well-known problem:

# maxpoll 9 is used to work around PLL/FLL flipping, which happens at
# exactly 1024 seconds (the default maxpoll value).  Another FreeBSD
# user recommended using 9 instead:
# http://lists.freebsd.org/pipermail/freebsd-stable/2006-December/031512.html

  I don't know if that has any connection to time(1) running slower -- but
  perhaps ntpd is aggressively adjusting your clock?
 
 It seems to be pretty stable when the machine is idle:
 
 % ntpq -c pe
  remote   refid  st t when poll reach   delay   offset  jitter
 ==
 *gw.catspoiler.o .GPS.1 u8   64  3770.168   -0.081   0.007
 
 Not too much degradation under CPU load:
 
 % ntpq -c pe
  remote   refid  st t when poll reach   delay   offset  jitter
 ==
 *gw.catspoiler.o .GPS.1 u   40   64  3770.166   -0.156   0.026
 
 I/O (dd if=/dev/ad6 of=/dev/null bs=512) doesn't appear to bother it
 much, either.
 
 % ntpq -c pe
  remote   refid  st t when poll reach   delay   offset  jitter
 ==
 *gw.catspoiler.o .GPS.1 u   35   64  3770.169   -0.106   0.009

Still speaking purely about ntpd:

The above doesn't indicate a single problem.  The deltas shown in both
delay, offset, and jitter are all 100% legitimate.  A dd (to induce more
interrupt use) isn't going to exacerbate the problem (depending on your
system configuration, IRQ setup, local APIC, etc.).

How about writing a small shell script that runs every minute in a
cronjob that does vmstat -i  /some/file.log?  Then when you see calcru
messages, look around the time frame where vmstat -i was run.  Look for
high interrupt rates, aside from those associated with cpuX devices.

Next, you need to let ntpd run for quite a bit longer than what you did
above.  Your poll maximum is only 64, indicating ntpd had recently been
restarted, or that your offset deviates greatly (my guess is ntpd being
restarted).  poll will increase over time (64, 128, 256, 512, and
usually max out at 1024), depending on how stable the clock is.  when
is a counter that increments, and does clock syncing (if needed) once it
reaches poll.  You'd see unstable system clock indications in your
syslog as well (indicated by actual +/- clock drift lines occurring
regularly.  These aren't the same as 2001/6001 PLL/FLL mode flipping).
Sorry if this is a bit paragraph/much to take in.

You might also try stopping ntpd, removing /var/db/ntpd.drift, and
restarting ntpd -- then check back in about 48 hours (no I'm not
kidding).  This is especially necessary if you've replaced the
motherboard or taken the disks from System A and stuck them in System B.

All that said: I'm not convinced ntpd has anything to do with your
problem.  EIST or EIST-like capabilities (such as Cool'n'Quiet) are
often the source of the problem.  device cpufreq might solve your
issue entirely, hard to say.

-- 
| Jeremy Chadwick   j...@parodius.com |
| Parodius Networking   http://www.parodius.com/ |
| UNIX Systems Administrator  Mountain View, CA, USA |
| Making life hard for others since 1977.  PGP: 4BD6C0CB |

___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-28 Thread Don Lewis 
On 28 Sep, Jeremy Chadwick wrote:
 On Tue, Sep 28, 2010 at 10:15:34AM -0700, Don Lewis wrote:
 My time source is another FreeBSD box with a GPS receiver on my LAN.  My
 other client machine isn't seeing these time jumps.  The only messages
 from ntp in its log from this period are these:
 
 Sep 23 04:12:23 mousie ntpd[]: kernel time sync status change 6001
 Sep 23 04:29:29 mousie ntpd[]: kernel time sync status change 2001
 Sep 24 03:55:24 mousie ntpd[]: kernel time sync status change 6001
 Sep 24 04:12:28 mousie ntpd[]: kernel time sync status change 2001
 
 I'm speaking purely about ntpd below this point -- almost certainly a
 separate problem/issue, but I'll explain it anyway.  I'm not under the
 impression that the calcru messages indicate RTC clock drift, but I'd
 need someone like John Baldwin to validate my statement.

I don't think the problems are directly related.  I think the calcru
messages get triggered by clcok frequency changes that get detected and
change the tick to usec conversion ratio.

 Back to ntpd: you can addressing the above messages by adding maxpoll
 9 to your server lines in ntp.conf.  The comment we use in our
 ntp.conf that documents the well-known problem:

Thanks I'll try that.

 # maxpoll 9 is used to work around PLL/FLL flipping, which happens at
 # exactly 1024 seconds (the default maxpoll value).  Another FreeBSD
 # user recommended using 9 instead:
 # http://lists.freebsd.org/pipermail/freebsd-stable/2006-December/031512.html
 
  I don't know if that has any connection to time(1) running slower -- but
  perhaps ntpd is aggressively adjusting your clock?
 
 It seems to be pretty stable when the machine is idle:
 
 % ntpq -c pe
  remote   refid  st t when poll reach   delay   offset  
 jitter
 ==
 *gw.catspoiler.o .GPS.1 u8   64  3770.168   -0.081   
 0.007
 
 Not too much degradation under CPU load:
 
 % ntpq -c pe
  remote   refid  st t when poll reach   delay   offset  
 jitter
 ==
 *gw.catspoiler.o .GPS.1 u   40   64  3770.166   -0.156   
 0.026
 
 I/O (dd if=/dev/ad6 of=/dev/null bs=512) doesn't appear to bother it
 much, either.
 
 % ntpq -c pe
  remote   refid  st t when poll reach   delay   offset  
 jitter
 ==
 *gw.catspoiler.o .GPS.1 u   35   64  3770.169   -0.106   
 0.009
 
 Still speaking purely about ntpd:
 
 The above doesn't indicate a single problem.  The deltas shown in both
 delay, offset, and jitter are all 100% legitimate.  A dd (to induce more
 interrupt use) isn't going to exacerbate the problem (depending on your
 system configuration, IRQ setup, local APIC, etc.).

I was hoping to do something to provoke clock interrupt loss.  I don't
see any problems when this machine is idle.  The last two times that the
calcru messages have occured where when I booted this machine to build a
bunch of ports.

I don't see any problems when this machine is idle.  Offset and jitter
always look really good whenever I've looked.



 How about writing a small shell script that runs every minute in a
 cronjob that does vmstat -i  /some/file.log?  Then when you see calcru
 messages, look around the time frame where vmstat -i was run.  Look for
 high interrupt rates, aside from those associated with cpuX devices.

Ok, I'll give this a try.  Just for reference, this is what is currently
reported:
% vmstat -i
interrupt  total   rate
irq0: clk   60683442   1000
irq1: atkbd0   6  0
irq8: rtc7765537127
irq9: acpi0   13  0
irq10: ohci0 ehci1+ 10275064169
irq11: fwohci0 ahc+   132133  2
irq12: psm0   21  0
irq14: ata090982  1
irq15: nfe0 ata1   18363  0

I'm not sure why I'm getting USB interrupts.  There aren't any USB
devices plugged into this machine.

# usbconfig dump_info
ugen0.1: OHCI root HUB nVidia at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) 
pwr=ON

ugen1.1: EHCI root HUB nVidia at usbus1, cfg=0 md=HOST spd=HIGH (480Mbps) 
pwr=ON

ugen2.1: OHCI root HUB nVidia at usbus2, cfg=0 md=HOST spd=FULL (12Mbps) 
pwr=ON

ugen3.1: EHCI root HUB nVidia at usbus3, cfg=0 md=HOST spd=HIGH (480Mbps) 
pwr=ON


 Next, you need to let ntpd run for quite a bit longer than what you did
 above.  Your poll maximum is only 64, indicating ntpd had recently been
 restarted, or that your offset deviates greatly (my guess is ntpd being
 restarted).  poll will increase over time (64, 128, 256, 512, and
 usually max out at 1024), depending on how stable the clock is.  when
 is a counter

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

2010-09-28 Thread Don Lewis 
On 28 Sep, Don Lewis wrote:


 % vmstat -i
 interrupt  total   rate
 irq0: clk   60683442   1000
 irq1: atkbd0   6  0
 irq8: rtc7765537127
 irq9: acpi0   13  0
 irq10: ohci0 ehci1+ 10275064169
 irq11: fwohci0 ahc+   132133  2
 irq12: psm0   21  0
 irq14: ata090982  1
 irq15: nfe0 ata1   18363  0
 
 I'm not sure why I'm getting USB interrupts.  There aren't any USB
 devices plugged into this machine.

Answer: irq 10 is also shared by vgapci0 and atapci1.

___
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to freebsd-stable-unsubscr...@freebsd.org

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

2010-09-28 Thread Don Lewis 
On 28 Sep, Jeremy Chadwick wrote:

 Still speaking purely about ntpd:
 
 The above doesn't indicate a single problem.  The deltas shown in both
 delay, offset, and jitter are all 100% legitimate.  A dd (to induce more
 interrupt use) isn't going to exacerbate the problem (depending on your
 system configuration, IRQ setup, local APIC, etc.).
 
 How about writing a small shell script that runs every minute in a
 cronjob that does vmstat -i  /some/file.log?  Then when you see calcru
 messages, look around the time frame where vmstat -i was run.  Look for
 high interrupt rates, aside from those associated with cpuX devices.

Looking at the timestamps of things and comparing to my logs, I
discovered that the last instance of ntp instability happened when I was
running make index in /usr/ports.  I tried it again with entertaining
results.  After a while, the machine became unresponsive.  I was logged
in over ssh and it stopped echoing keystrokes.  In parallel I was
running a script that echoed the date, the results of vmstat -i, and
the results of ntpq -c pe.  The latter showed jitter and offset going
insane.  Eventually make index finished and the machine was responsive
again, but the time was way off and ntpd croaked because the necessary
time correction was too large.  Nothing else anomalous showed up in the
logs.  Hmn, about half an hour after ntpd died I started my CPU time
accounting test and two minutes into that test I got a spew of calcru
messages ...

Tue Sep 28 14:52:27 PDT 2010
interrupt  total   rate
irq0: clk   64077827999
irq1: atkbd0  26  0
irq8: rtc8199966127
irq9: acpi0   19  0
irq10: ohci0 ehci1+ 10356112161
irq11: fwohci0 ahc+   132133  2
irq12: psm0   27  0
irq14: ata096064  1
irq15: nfe0 ata1   23350  0
Total   82885524   1293
 remote   refid  st t when poll reach   delay   offset  jitter
==
*gw.catspoiler.o .GPS.1 u  137  128  3770.1950.111   0.030

Tue Sep 28 14:53:27 PDT 2010
interrupt  total   rate
irq0: clk   64137854999
irq1: atkbd0  26  0
irq8: rtc8207648127
irq9: acpi0   19  0
irq10: ohci0 ehci1+ 10360184161
irq11: fwohci0 ahc+   132133  2
irq12: psm0   27  0
irq14: ata096154  1
irq15: nfe0 ata1   23379  0
Total   82957424   1293
 remote   refid  st t when poll reach   delay   offset  jitter
==
*gw.catspoiler.o .GPS.1 u   56  128  3770.1950.111 853895.

Tue Sep 28 14:54:27 PDT 2010
interrupt  total   rate
irq0: clk   64197881999
irq1: atkbd0  26  0
irq8: rtc8215329127
irq9: acpi0   21  0
irq10: ohci0 ehci1+ 10360777161
irq11: fwohci0 ahc+   132133  2
irq12: psm0   27  0
irq14: ata096244  1
irq15: nfe0 ata1   23405  0
Total   83025843   1293
 remote   refid  st t when poll reach   delay   offset  jitter
==
*gw.catspoiler.o .GPS.1 u  116  128  3770.1950.111 853895.

Tue Sep 28 14:55:27 PDT 2010
interrupt  total   rate
irq0: clk   64257907999
irq1: atkbd0  26  0
irq8: rtc8223011127
irq9: acpi0   21  0
irq10: ohci0 ehci1+ 10360836161
irq11: fwohci0 ahc+   132133  2
irq12: psm0   27  0
irq14: ata096334  1
irq15: nfe0 ata1   23424  0
Total   83093719   1292
 remote   refid  st t when poll reach   delay   offset  jitter
==
 gw.catspoiler.o .GPS.1 u   48  128  3770.197  2259195 2091608

Tue Sep 28 14:56:27 PDT 2010
interrupt  total   rate
irq0: clk   64317933999
irq1: atkbd0

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

2010-09-28 Thread Don Lewis 
On 28 Sep, Don Lewis wrote:

 Looking at the timestamps of things and comparing to my logs, I
 discovered that the last instance of ntp instability happened when I was
 running make index in /usr/ports.  I tried it again with entertaining
 results.  After a while, the machine became unresponsive.  I was logged
 in over ssh and it stopped echoing keystrokes.  In parallel I was
 running a script that echoed the date, the results of vmstat -i, and
 the results of ntpq -c pe.  The latter showed jitter and offset going
 insane.  Eventually make index finished and the machine was responsive
 again, but the time was way off and ntpd croaked because the necessary
 time correction was too large.  Nothing else anomalous showed up in the
 logs.  Hmn, about half an hour after ntpd died I started my CPU time
 accounting test and two minutes into that test I got a spew of calcru
 messages ...

I tried this experiment again using a kernel with WITNESS and
DEBUG_VFS_LOCKS compiled in, and pinging this machine from another.
Things look normal for a while, then the ping times get huge for a while
and then recover.

64 bytes from 192.168.101.3: icmp_seq=1169 ttl=64 time=0.135 ms
64 bytes from 192.168.101.3: icmp_seq=1170 ttl=64 time=0.141 ms
64 bytes from 192.168.101.3: icmp_seq=1171 ttl=64 time=0.130 ms
64 bytes from 192.168.101.3: icmp_seq=1172 ttl=64 time=0.131 ms
64 bytes from 192.168.101.3: icmp_seq=1173 ttl=64 time=0.128 ms
64 bytes from 192.168.101.3: icmp_seq=1174 ttl=64 time=38232.140 ms
64 bytes from 192.168.101.3: icmp_seq=1175 ttl=64 time=37231.309 ms
64 bytes from 192.168.101.3: icmp_seq=1176 ttl=64 time=36230.470 ms
64 bytes from 192.168.101.3: icmp_seq=1177 ttl=64 time=35229.632 ms
64 bytes from 192.168.101.3: icmp_seq=1178 ttl=64 time=34228.791 ms
64 bytes from 192.168.101.3: icmp_seq=1179 ttl=64 time=33227.953 ms
64 bytes from 192.168.101.3: icmp_seq=1180 ttl=64 time=32227.091 ms
64 bytes from 192.168.101.3: icmp_seq=1181 ttl=64 time=31226.262 ms
64 bytes from 192.168.101.3: icmp_seq=1182 ttl=64 time=30225.425 ms
64 bytes from 192.168.101.3: icmp_seq=1183 ttl=64 time=29224.597 ms
64 bytes from 192.168.101.3: icmp_seq=1184 ttl=64 time=28223.757 ms
64 bytes from 192.168.101.3: icmp_seq=1185 ttl=64 time=27222.918 ms
64 bytes from 192.168.101.3: icmp_seq=1186 ttl=64 time=26222.086 ms
64 bytes from 192.168.101.3: icmp_seq=1187 ttl=64 time=25221.164 ms
64 bytes from 192.168.101.3: icmp_seq=1188 ttl=64 time=24220.407 ms
64 bytes from 192.168.101.3: icmp_seq=1189 ttl=64 time=23219.575 ms
64 bytes from 192.168.101.3: icmp_seq=1190 ttl=64 time=22218.737 ms
64 bytes from 192.168.101.3: icmp_seq=1191 ttl=64 time=21217.905 ms
64 bytes from 192.168.101.3: icmp_seq=1192 ttl=64 time=20217.066 ms
64 bytes from 192.168.101.3: icmp_seq=1193 ttl=64 time=19216.228 ms
64 bytes from 192.168.101.3: icmp_seq=1194 ttl=64 time=18215.333 ms
64 bytes from 192.168.101.3: icmp_seq=1195 ttl=64 time=17214.503 ms
64 bytes from 192.168.101.3: icmp_seq=1196 ttl=64 time=16213.720 ms
64 bytes from 192.168.101.3: icmp_seq=1197 ttl=64 time=15210.912 ms
64 bytes from 192.168.101.3: icmp_seq=1198 ttl=64 time=14210.044 ms
64 bytes from 192.168.101.3: icmp_seq=1199 ttl=64 time=13209.194 ms
64 bytes from 192.168.101.3: icmp_seq=1200 ttl=64 time=12208.376 ms
64 bytes from 192.168.101.3: icmp_seq=1201 ttl=64 time=11207.536 ms
64 bytes from 192.168.101.3: icmp_seq=1202 ttl=64 time=10206.694 ms
64 bytes from 192.168.101.3: icmp_seq=1203 ttl=64 time=9205.816 ms
64 bytes from 192.168.101.3: icmp_seq=1204 ttl=64 time=8205.014 ms
64 bytes from 192.168.101.3: icmp_seq=1205 ttl=64 time=7204.186 ms
64 bytes from 192.168.101.3: icmp_seq=1206 ttl=64 time=6203.294 ms
64 bytes from 192.168.101.3: icmp_seq=1207 ttl=64 time=5202.510 ms
64 bytes from 192.168.101.3: icmp_seq=1208 ttl=64 time=4201.677 ms
64 bytes from 192.168.101.3: icmp_seq=1209 ttl=64 time=3200.851 ms
64 bytes from 192.168.101.3: icmp_seq=1210 ttl=64 time=2200.013 ms
64 bytes from 192.168.101.3: icmp_seq=1211 ttl=64 time=1199.100 ms
64 bytes from 192.168.101.3: icmp_seq=1212 ttl=64 time=198.331 ms
64 bytes from 192.168.101.3: icmp_seq=1213 ttl=64 time=0.129 ms
64 bytes from 192.168.101.3: icmp_seq=1214 ttl=64 time=58223.470 ms
64 bytes from 192.168.101.3: icmp_seq=1215 ttl=64 time=57222.637 ms
64 bytes from 192.168.101.3: icmp_seq=1216 ttl=64 time=56221.800 ms
64 bytes from 192.168.101.3: icmp_seq=1217 ttl=64 time=55220.960 ms
64 bytes from 192.168.101.3: icmp_seq=1218 ttl=64 time=54220.116 ms
64 bytes from 192.168.101.3: icmp_seq=1219 ttl=64 time=53219.282 ms
64 bytes from 192.168.101.3: icmp_seq=1220 ttl=64 time=52218.444 ms
64 bytes from 192.168.101.3: icmp_seq=1221 ttl=64 time=51217.618 ms
64 bytes from 192.168.101.3: icmp_seq=1222 ttl=64 time=50216.778 ms
64 bytes from 192.168.101.3: icmp_seq=1223 ttl=64 time=49215.932 ms
64 bytes from 192.168.101.3: icmp_seq=1224 ttl=64 time=48215.095 ms
64 bytes from 192.168.101.3: icmp_seq=1225 ttl=64 time=47214.262 ms
64 bytes from 192.168.101.3: icmp_seq=1226

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

2010-09-27 Thread Don Lewis 
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


I'm not sure how long this problem has been present. I do remember
seeing the calcru messages with an August 23rd kernel.  I have not seen
the calcru messages when running -CURRENT on the same hardware.  I also
have not seen this same problem on my other Athlon 64 box running the
August 23rd kernel.

Before reboot:
# sysctl kern.timecounter
kern.timecounter.tick: 1
kern.timecounter.choice: TSC(800) ACPI-fast(1000) i8254(0) dummy(-100)
kern.timecounter.hardware: ACPI-fast
kern.timecounter.stepwarnings: 0
kern.timecounter.tc.i8254.mask: 4294967295
kern.timecounter.tc.i8254.counter: 3534
kern.timecounter.tc.i8254.frequency: 1193182
kern.timecounter.tc.i8254.quality: 0
kern.timecounter.tc.ACPI-fast.mask: 16777215
kern.timecounter.tc.ACPI-fast.counter: 8685335
kern.timecounter.tc.ACPI-fast.frequency: 3579545
kern.timecounter.tc.ACPI-fast.quality: 1000
kern.timecounter.tc.TSC.mask: 4294967295
kern.timecounter.tc.TSC.counter: 2204228369
kern.timecounter.tc.TSC.frequency: 2500018183
kern.timecounter.tc.TSC.quality: 800
kern.timecounter.invariant_tsc: 0

After reboot:
% sysctl kern.timecounter
kern.timecounter.tick: 1
kern.timecounter.choice: TSC(800) ACPI-fast(1000) i8254(0) dummy(-100)
kern.timecounter.hardware: ACPI-fast
kern.timecounter.stepwarnings: 0
kern.timecounter.tc.i8254.mask: 4294967295
kern.timecounter.tc.i8254.counter: 2241
kern.timecounter.tc.i8254.frequency: 1193182
kern.timecounter.tc.i8254.quality: 0
kern.timecounter.tc.ACPI-fast.mask: 16777215
kern.timecounter.tc.ACPI-fast.counter: 4636239
kern.timecounter.tc.ACPI-fast.frequency: 3579545
kern.timecounter.tc.ACPI-fast.quality: 1000
kern.timecounter.tc.TSC.mask:

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

2010-09-27 Thread Jeremy Chadwick 
On Mon, Sep 27, 2010 at 09:25:10PM -0700, Don Lewis wrote:
 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
 
 
 I'm not sure how long this problem has been present. I do remember
 seeing the calcru messages with an August 23rd kernel.  I have not seen
 the calcru messages when running -CURRENT on the same hardware.  I also
 have not seen this same problem on my other Athlon 64 box running the
 August 23rd kernel.
 
 Before reboot:
 # sysctl kern.timecounter
 kern.timecounter.tick: 1
 kern.timecounter.choice: TSC(800) ACPI-fast(1000) i8254(0) dummy(-100)
 kern.timecounter.hardware: ACPI-fast
 kern.timecounter.stepwarnings: 0
 kern.timecounter.tc.i8254.mask: 4294967295
 kern.timecounter.tc.i8254.counter: 3534
 kern.timecounter.tc.i8254.frequency: 1193182
 kern.timecounter.tc.i8254.quality: 0
 kern.timecounter.tc.ACPI-fast.mask: 16777215
 kern.timecounter.tc.ACPI-fast.counter: 8685335
 kern.timecounter.tc.ACPI-fast.frequency: 3579545
 kern.timecounter.tc.ACPI-fast.quality: 1000
 kern.timecounter.tc.TSC.mask: 4294967295
 kern.timecounter.tc.TSC.counter: 2204228369
 kern.timecounter.tc.TSC.frequency: 2500018183
 kern.timecounter.tc.TSC.quality: 800
 kern.timecounter.invariant_tsc: 0
 
 After reboot:
 % sysctl kern.timecounter
 kern.timecounter.tick: 1
 kern.timecounter.choice: TSC(800) ACPI-fast(1000) i8254(0) dummy(-100)
 kern.timecounter.hardware: ACPI-fast
 kern.timecounter.stepwarnings: 0
 kern.timecounter.tc.i8254.mask: 4294967295
 kern.timecounter.tc.i8254.counter: 2241
 kern.timecounter.tc.i8254.frequency: 1193182
 kern.timecounter.tc.i8254.quality: 0
 kern.timecounter.tc.ACPI-fast.mask: 16777215