Date: Sat, 5 Oct 2002 15:10:12 -0700 (PDT) From: "Bjoern A.Zeeb" <bzeeb@zabbadoz.net> To: freebsd-bugs@FreeBSD.org Subject: Re: i386/43491: microuptime () went backwards Message-ID: <200210052210.g95MACBZ011345@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
The following reply was made to PR i386/43491; it has been noted by GNATS.
From: Bjoern A.Zeeb <bzeeb@zabbadoz.net>
To: FreeBSD-gnats-submit@freebsd.org
Cc: Paul LeDuc <paul.leduc@appliedheuristics.com>
Subject: Re: i386/43491: microuptime () went backwards
Date: Sat, 5 Oct 2002 22:04:35 +0000 (UTC)
>Submitter-Id: current-users
>Originator: Bjoern A. Zeeb
>Organization:
>Confidential: no
>Synopsis: Re: i386/43491: microuptime () went backwards
>Severity: critical
>Priority: medium
>Category: kern
>Class: sw-bug
>Release: FreeBSD 4.7-RC i386
>Environment:
System: FreeBSD e0-0.zab2.int.zabbadoz.net 4.7-RC FreeBSD 4.7-RC #1: Fri Oct 4 18:45:10 UTC 2002 bz@e0-0.zab2.int.zabbadoz.net:/usr/src/obj/usr/src/RELENG_4/src/sys/ZAB2-2002092701 i386
Copyright (c) 1992-2002 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.7-RC #1: Fri Oct 4 18:45:10 UTC 2002
bz@e0-0.zab2.int.zabbadoz.net:/usr/src/obj/usr/src/RELENG_4/src/sys/ZAB2-2002092701
Timecounter "i8254" frequency 1193182 Hz
CPU: Pentium III/Pentium III Xeon/Celeron (499.15-MHz 686-class CPU)
Origin = "GenuineIntel" Id = 0x673 Stepping = 3
Features=0x383f9ff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,MMX,FXSR,SSE>
real memory = 536805376 (524224K bytes)
avail memory = 517132288 (505012K bytes)
Preloaded elf kernel "kernel" at 0xc050e000.
Pentium Pro MTRR support enabled
md0: Malloc disk
Using $PIR table, 7 entries at 0xc00fd3b0
npx0: <math processor> on motherboard
npx0: INT 16 interface
pcib0: <Host to PCI bridge> on motherboard
pci0: <PCI bus> on pcib0
pcib2: <VIA 82C598MVP (Apollo MVP3) PCI-PCI (AGP) bridge> at device 1.0 on pci0
pci1: <PCI bus> on pcib2
pci1: <ATI Rage128-RL graphics accelerator> at 0.0 irq 11
isab0: <VIA 82C596B PCI-ISA bridge> at device 7.0 on pci0
isa0: <ISA bus> on isab0
atapci0: <VIA 82C596 ATA66 controller> port 0xe000-0xe00f at device 7.1 on pci0
ata0: at 0x1f0 irq 14 on atapci0
ata1: at 0x170 irq 15 on atapci0
pci0: <unknown card> (vendor=0x1106, dev=0x3050) at 7.3
pci0: <unknown card> (vendor=0x1073, dev=0x000c) at 12.0 irq 5
fxp0: <Intel Pro 10/100B/100+ Ethernet> port 0xe800-0xe83f mem 0xe7400000-0xe741ffff,0xe7428000-0xe7428fff irq 10 at device 14.0 on pci0
fxp0: Ethernet address 00:02:b3:60:7d:b6
inphy0: <i82555 10/100 media interface> on miibus0
inphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
pci0: <unknown card> (vendor=0x134d, dev=0x7890) at 16.0 irq 12
pcib1: <Host to PCI bridge> on motherboard
pci2: <PCI bus> on pcib1
orm0: <Option ROMs> at iomem 0xc0000-0xc7fff,0xc8000-0xc97ff,0xef000-0xeffff 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
atkbd0: <AT Keyboard> flags 0x1 irq 1 on atkbdc0
kbd0 at atkbd0
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=0x300>
sio0 at port 0x3f8-0x3ff irq 4 flags 0x10 on isa0
sio0: type 16550A
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/16 bytes threshold
plip0: <PLIP network interface> on ppbus0
lpt0: <Printer> on ppbus0
lpt0: Interrupt-driven port
ppi0: <Parallel I/O> on ppbus0
ad0: 14664MB <IBM-DJNA-351520> [29795/16/63] at ata0-master UDMA66
ad1: 19470MB <IBM-DJNA-352030> [39560/16/63] at ata0-slave UDMA66
ad2: 57241MB <ST360020A> [116301/16/63] at ata1-master UDMA66
Mounting root from ufs:/dev/ad0s1a
bz@e0-0:~> sysctl kern.timecounter
kern.timecounter.method: 0
kern.timecounter.hardware: i8254
>Description:
With / after heavy disc IO I also saw this problems: selct(2) failed too
and the kernel bleated (got ~45MB kern.log till I got a usable terminal to
reboot the machine):
--- some few lines ---
Oct 5 23:28:22 e0-0 /kernel: microuptime() went backwards (100768.094319 -> 100768.084713)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.128400 -> 100768.116302)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.217553 -> 100768.200736)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.248408 -> 100768.242961)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.279782 -> 100768.-695144269)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.316998 -> 100768.-695103619)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.401070 -> 100768.352367)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.401070 -> 100768.375326)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.401070 -> 100768.378034)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.401070 -> 100768.379457)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.412284 -> 100768.411343)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.458296 -> 100768.454611)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.510417 -> 100768.487032)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.503602 -> 100768.492363)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.545493 -> 100768.504730)
Oct 5 23:28:22 e0-0 /kernel: microuptime() went backwards (100768.539489 -> 100768.528893)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.539489 -> 100768.525594)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.598427 -> 100768.588391)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.623375 -> 100768.611491)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.692954 -> 100768.680214)
Oct 5 23:28:24 e0-0 /kernel: calcru: negative time of -689194177 usec for pid 298 (qmgr)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100768.717821 -> 100768.716886)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100768.754219 -> 100768.725387)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100768.801615 -> 100768.791238)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100768.839133 -> 100768.831843)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100768.859355 -> 100768.835970)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100768.859355 -> 100768.844127)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100768.864647 -> 100768.842601)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100768.864647 -> 100768.-694516988)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100768.908268 -> 100768.895184)
Oct 5 23:28:23 e0-0 /kernel: microuptime() went backwards (100768.962801 -> 100768.939847)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100769.256270 -> 100769.-695136753)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100769.322563 -> 100769.298534)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100769.322563 -> 100769.300168)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100769.322563 -> 100769.307380)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100769.385091 -> 100769.353553)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100769.396938 -> 100769.386771)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100769.396938 -> 100769.-694994276)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100769.396938 -> 100769.-694974749)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100769.441419 -> 100769.431813)
Oct 5 23:28:24 e0-0 /kernel: microuptime() went backwards (100769.549778 -> 100769.-694865476)
--- end ---
e0-0# grep microuptime /var/log/kern.log | wc -l
494707
System load was > 3.5 because of intensive logging and some apps racing because
select failed :(
>How-To-Repeat:
p.ex. cp -pr /usr to another disc
>Fix:
though read that you cannot really fix it there is one thing you might
want to do:
remove the time changes from each and every printf so syslog can
aggregate the messages and simply print
"last message repeated 490345 times".
if you need it to be dumped (though you cannot correct anything with
this information) add a flag for those people who want to see the
addition information.
This would at least reduce disc IO and save some bytes ;-) and perhaps
help to stop the system from misbehaving.
To Unsubscribe: send mail to majordomo@FreeBSD.org
with "unsubscribe freebsd-bugs" in the body of the message
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200210052210.g95MACBZ011345>