thr3ads.net - freebsd stable - Time jumping on both 4.x and 5.x ... [Nov 2003]

If this information is useful, please help other people find it:
Share via:

Marc G. Fournier

2003-Nov-28 17:35 UTC

Time jumping on both 4.x and 5.x ...

In trying to isolate an issue where the PostgreSQL 'explain analyze' is
showing "odd results" (namely, negative time estimates on queries),
Tom
Lane wrote a quick C program to test gettimeofday() (program attached) ...
the results on a 4.9-PRERELEASE kernel of Sep 20 14:16:48 ADT 2003 shows:

neptune# time ./timetest
out of order tv_sec: 1070068479 99040, prev 1070069174 725235
out of order tv_usec: 1070068479 99040, prev 1070069174 725235
out of order tv_sec: 1070069175 19687, prev 1070068479 99040
out of order tv_usec: 1070069175 19687, prev 1070068479 99040
out of order tv_sec: 1070068499 99377, prev 1070069194 625573
out of order tv_usec: 1070068499 99377, prev 1070069194 625573
out of order tv_sec: 1070069194 808542, prev 1070068499 99377
^C1.171u 23.461s 0:24.68 99.7%  5+169k 1+0io 0pf+0w

One person on the list has tried the same script on a 5.2 kernel, and
reports seeing similar results, but after a longer period of time (~30min)
...

In most (all?) cases, the offset appears to be ~+/-695 secs ... Linux ppl
on the list, running the same problem, seem to be able to reproduce the
issue, except they are only finding differences of 1 microsecond, and then
only on older kernels (2.2.x, apparently) ... those running newer Linux
kernels are reporting a clean run ...

Known problem?

----
Marc G. Fournier           Hub.Org Networking Services (http://www.hub.org)
Email: scrappy@hub.org           Yahoo!: yscrappy              ICQ: 7615664
-------------- next part --------------
#include <stdio.h>
#include <sys/time.h>

int
main()
{
	struct timeval prevtime;
	struct timeval curtime;

	gettimeofday(&prevtime, NULL);

	for (;;)
	{
		gettimeofday(&curtime, NULL);

		if (curtime.tv_usec < 0 || curtime.tv_usec >= 1000000)
			fprintf(stderr, "bogus tv_usec: %ld %ld, prev %ld %ld\n",
					(long int) curtime.tv_sec,
					(long int) curtime.tv_usec,
					(long int) prevtime.tv_sec,
					(long int) prevtime.tv_usec);

		if (curtime.tv_sec < prevtime.tv_sec ||
			curtime.tv_sec > prevtime.tv_sec + 1)
			fprintf(stderr, "out of order tv_sec: %ld %ld, prev %ld %ld\n",
					(long int) curtime.tv_sec,
					(long int) curtime.tv_usec,
					(long int) prevtime.tv_sec,
					(long int) prevtime.tv_usec);

		if (curtime.tv_usec < prevtime.tv_usec &&
			curtime.tv_sec != prevtime.tv_sec + 1)
			fprintf(stderr, "out of order tv_usec: %ld %ld, prev %ld %ld\n",
					(long int) curtime.tv_sec,
					(long int) curtime.tv_usec,
					(long int) prevtime.tv_sec,
					(long int) prevtime.tv_usec);

		prevtime = curtime;
	}

	return 0;
}

Kris Kennaway

2003-Nov-28 18:53 UTC

head link

Time jumping on both 4.x and 5.x ...

On Fri, Nov 28, 2003 at 09:32:30PM -0400, Marc G. Fournier
wrote:> 
> In trying to isolate an issue where the PostgreSQL 'explain
analyze' is
> showing "odd results" (namely, negative time estimates on
queries), Tom
> Lane wrote a quick C program to test gettimeofday() (program attached) ...
> the results on a 4.9-PRERELEASE kernel of Sep 20 14:16:48 ADT 2003 shows:
> 
> neptune# time ./timetest
> out of order tv_sec: 1070068479 99040, prev 1070069174 725235
> out of order tv_usec: 1070068479 99040, prev 1070069174 725235
> out of order tv_sec: 1070069175 19687, prev 1070068479 99040
> out of order tv_usec: 1070069175 19687, prev 1070068479 99040
> out of order tv_sec: 1070068499 99377, prev 1070069194 625573
> out of order tv_usec: 1070068499 99377, prev 1070069194 625573
> out of order tv_sec: 1070069194 808542, prev 1070068499 99377
> ^C1.171u 23.461s 0:24.68 99.7%  5+169k 1+0io 0pf+0w
> 
> One person on the list has tried the same script on a 5.2 kernel, and
> reports seeing similar results, but after a longer period of time (~30min)
> ...
What hardware, kernel configuration, etc?  Do you have a misconfigured
ntpd/timed that is manually flapping the time around?

I've run that test for a few minutes on 4.9 without problems.

Kris
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 187 bytes
Desc: not available
Url :
http://lists.freebsd.org/pipermail/freebsd-stable/attachments/20031128/74629ac6/attachment.bin

Don Bowman

2003-Nov-29 08:37 UTC

head link

Time jumping on both 4.x and 5.x ...

From: Kris Kennaway [mailto:kris@obsecurity.org]> 
> On Sat, Nov 29, 2003 at 11:32:28AM +0100, Michael Nottebrock wrote:
> Content-Description: signed data
> > On Saturday 29 November 2003 09:19, Kris Kennaway wrote:
> > >
> > > Are all affected machines multi-processor?
> > 
> > None. Both are i386 UP (although the 4.9-RELEASE box is 
> running an SMP-enabled 
> > kernel).
> 
> I didn't think 4.x SMP kernels could run on a UP machine.
They can if the machine has an APIC. ie most P3 and newer
boards will run a MP kernel even if only one processor
is installed.

For me, the bug reproduces on 4.7, and if I set
kern.timecounter.method=1, the problem goes away. I've
reproduced on both TSC and i8254.

--don

Oivind H. Danielsen

2003-Nov-29 12:26 UTC

head link

Time jumping on both 4.x and 5.x ...

> In most (all?) cases, the offset appears to be ~+/-695 secs ...
I can also report ~695 second time diffs.

The machine runs ntpd.

syslog:
Sep 28 11:05:26 /kernel: microuptime ) went backwards  10360654
535206 -> 10359959 143722) ->Diff: -695
Oct 17 17:33:29 /kernel: microuptime ) went backwards  12025537
375872 -> 12024841 976402) ->Diff: -696
Oct 19 21:49:00 /kernel: microuptime ) went backwards  12213668
882643 -> 12212973 489255) ->Diff: -695
Nov  2 03:17:11 /kernel: microuptime ) went backwards  13360159
345495 -> 13359463 951497) ->Diff: -696
Nov  6 00:47:11 /kernel: microuptime ) went backwards  13696759
218141 -> 13696063 823799) ->Diff: -696
Nov  8 08:39:00 /kernel: microuptime ) went backwards  13897869
155436 -> 13897173 758138) ->Diff: -696
Nov 28 04:09:01 /kernel: microuptime ) went backwards  15609669
581130 -> 15608974 186453) ->Diff: -695
Nov 29 11:20:08 /kernel: microuptime ) went backwards  15721936
948706 -> 15721241 548127) ->Diff: -695

sysctl:
kern.timecounter.method: 0
kern.timecounter.hardware: i8254

kernel config:
ipfw2, dummynet, divert, vlan, bpf, HZ=1000

dmesg:
Copyright (c) 1992-2003 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
	The Regents of the University of California. All rights reserved.
FreeBSD 4.8-RELEASE #0: Tue Apr 22 13:02:11 CEST 2003
Timecounter "i8254"  frequency 1193182 Hz
CPU: AMD Athlon(TM) XP 2000+ (1662.38-MHz 686-class CPU)
  Origin = "AuthenticAMD"  Id = 0x662  Stepping = 2

Features=0x383fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,
MCA,CMOV,PAT,PSE36,MMX,FXSR,SSE>
  AMD Features=0xc0400000<AMIE,DSP,3DNow!>
real memory  = 503234560 (491440K bytes)
avail memory = 485478400 (474100K bytes)
Preloaded elf kernel "kernel" at 0xc03ea000.
Pentium Pro MTRR support enabled
md0: Malloc disk
Using $PIR table, 10 entries at 0xc00f20b0
npx0: <math processor> on motherboard
npx0: INT 16 interface
pcib0: <Host to PCI bridge> on motherboard
pci0: <PCI bus> on pcib0
pci0: <unknown card> (vendor=0x10de, dev=0x01ac) at 0.1
pci0: <unknown card> (vendor=0x10de, dev=0x01ad) at 0.2
pci0: <unknown card> (vendor=0x10de, dev=0x01aa) at 0.3
isab0: <PCI to ISA bridge (vendor=10de device=01b2)> at device 1.0 on
pci0
isa0: <ISA bus> on isab0
pci0: <unknown card> (vendor=0x10de, dev=0x01b4) at 1.1 irq 5
ohci0: <OHCI (generic) USB controller> mem 0xe7000000-0xe7000fff irq 10
at device 2.0 on pci0
usb0: OHCI version 1.0
usb0: SMM does not respond, resetting
usb0: <OHCI (generic) USB controller> on ohci0
usb0: USB revision 1.0
uhub0: (0x10de) OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 3 ports with 3 removable, self powered
ohci1: <OHCI (generic) USB controller> mem 0xe6800000-0xe6800fff irq 10
at device 3.0 on pci0
usb1: OHCI version 1.0
usb1: <OHCI (generic) USB controller> on ohci1
usb1: USB revision 1.0
uhub1: (0x10de) OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 3 ports with 3 removable, self powered
pci0: <unknown card> (vendor=0x10de, dev=0x01c3) at 4.0 irq 10
pci0: <unknown card> (vendor=0x10de, dev=0x01b0) at 5.0 irq 5
pci0: <unknown card> (vendor=0x10de, dev=0x01b1) at 6.0 irq 11
pcib1: <PCI to PCI bridge (vendor=10de device=01b8)> at device 8.0 on
pci0
pci1: <PCI bus> on pcib1
pcib2: <DEC 21150 PCI-PCI bridge> at device 6.0 on pci1
pci2: <PCI bus> on pcib2
fxp0: <Intel Pro 10/100B/100+ Ethernet> port 0xb800-0xb83f mem
0xe4000000-0xe40fffff,0xe4800000-0xe4800fff irq 5 at device 4.0 on pci2
fxp0: Ethernet address 00:08:9b:14:72:61
inphy0: <i82555 10/100 media interface> on miibus0
inphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
fxp1: <Intel Pro 10/100B/100+ Ethernet> port 0xb400-0xb43f mem
0xe3000000-0xe30fffff,0xe3800000-0xe3800fff irq 5 at device 5.0 on pci2
fxp1: Ethernet address 00:08:9b:14:72:62
inphy1: <i82555 10/100 media interface> on miibus1
inphy1:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
fxp2: <Intel Pro 10/100B/100+ Ethernet> port 0xb000-0xb03f mem
0xe2000000-0xe20fffff,0xe2800000-0xe2800fff irq 5 at device 6.0 on pci2
fxp2: Ethernet address 00:08:9b:14:71:a9
inphy2: <i82555 10/100 media interface> on miibus2
inphy2:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
fxp3: <Intel Pro 10/100B/100+ Ethernet> port 0xa800-0xa83f mem
0xe1000000-0xe10fffff,0xe1800000-0xe1800fff irq 5 at device 7.0 on pci2
fxp3: Ethernet address 00:08:9b:14:71:aa
inphy3: <i82555 10/100 media interface> on miibus3
inphy3:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
atapci0: <nVIDIA nForce ATA100 controller> port 0x9800-0x980f at device
9.0 on pci0
ata0: at 0x1f0 irq 14 on atapci0
ata1: at 0x170 irq 15 on atapci0
pcib3: <PCI to PCI bridge (vendor=10de device=01b7)> at device 30.0 on
pci0
pci3: <PCI bus> on pcib3
pci3: <NVidia model 01a0 graphics accelerator> at 0.0 irq 11
orm0: <Option ROM> at iomem 0xd0000-0xd3fff on isa0
fdc0: <NEC 72065B or clone> at port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on
isa0
fdc0: FIFO enabled, 8 bytes threshold
fd0: <1440-KB 3.5" drive> on fdc0 drive 0
atkbdc0: <Keyboard controller (i8042)> at port 0x60,0x64 on isa0
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on
isa0
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x100>
sio0 at port 0x3f8-0x3ff irq 4 flags 0x10 on isa0
sio0: type 16550A, console
sio1 at port 0x2f8-0x2ff irq 3 on isa0
sio1: type 16550A
ppc0: <Parallel port> at port 0x378-0x37f irq 7 on isa0
ppc0: SMC-like chipset (ECP/EPP/PS2/NIBBLE) in COMPATIBLE mode
ppc0: FIFO with 16/16/9 bytes threshold
ipfw2 initialized, divert enabled, rule-based forwarding enabled,
default to deny, logging limited to 100 packets/entry by default
DUMMYNET initialized (011031)
ad0: 78533MB <IC35L080AVVA07-0> [159560/16/63] at ata0-master PIO4
Mounting root from ufs:/dev/ad0s1a


Best Regards,

Oivind H. Danielsen

freebsd stable - Nov 2003 - Time jumping on both 4.x and 5.x ...

Time jumping on both 4.x and 5.x ...

Time jumping on both 4.x and 5.x ...

Time jumping on both 4.x and 5.x ...

Time jumping on both 4.x and 5.x ...