From owner-freebsd-bugs  Sat Oct  5 15:10:17 2002
Delivered-To: freebsd-bugs@hub.freebsd.org
Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125])
	by hub.freebsd.org (Postfix) with ESMTP id 4EF7337B401
	for <freebsd-bugs@hub.freebsd.org>; Sat,  5 Oct 2002 15:10:13 -0700 (PDT)
Received: from freefall.freebsd.org (freefall.freebsd.org [216.136.204.21])
	by mx1.FreeBSD.org (Postfix) with ESMTP id D463943E81
	for <freebsd-bugs@hub.freebsd.org>; Sat,  5 Oct 2002 15:10:12 -0700 (PDT)
	(envelope-from gnats@FreeBSD.org)
Received: from freefall.freebsd.org (gnats@localhost [127.0.0.1])
	by freefall.freebsd.org (8.12.6/8.12.6) with ESMTP id g95MACCo011346
	for <freebsd-bugs@freefall.freebsd.org>; Sat, 5 Oct 2002 15:10:12 -0700 (PDT)
	(envelope-from gnats@freefall.freebsd.org)
Received: (from gnats@localhost)
	by freefall.freebsd.org (8.12.6/8.12.6/Submit) id g95MACBZ011345;
	Sat, 5 Oct 2002 15:10:12 -0700 (PDT)
Date: Sat, 5 Oct 2002 15:10:12 -0700 (PDT)
Message-Id: <200210052210.g95MACBZ011345@freefall.freebsd.org>
To: freebsd-bugs@FreeBSD.org
Cc: 
From: "Bjoern A.Zeeb" <bzeeb@zabbadoz.net>
Subject: Re: i386/43491: microuptime () went backwards
Reply-To: "Bjoern A.Zeeb" <bzeeb@zabbadoz.net>
Sender: owner-freebsd-bugs@FreeBSD.ORG
Precedence: bulk
List-ID: <freebsd-bugs.FreeBSD.ORG>
List-Archive: <http://docs.freebsd.org/mail/> (Web Archive)
List-Help: <mailto:majordomo@FreeBSD.ORG?subject=help> (List Instructions)
List-Subscribe: <mailto:majordomo@FreeBSD.ORG?subject=subscribe%20freebsd-bugs>
List-Unsubscribe: <mailto:majordomo@FreeBSD.ORG?subject=unsubscribe%20freebsd-bugs>
X-Loop: FreeBSD.org

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