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>