Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S965643AbXA3Rjp (ORCPT ); Tue, 30 Jan 2007 12:39:45 -0500 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S965642AbXA3Rjp (ORCPT ); Tue, 30 Jan 2007 12:39:45 -0500 Received: from smtp4-g19.free.fr ([212.27.42.30]:55058 "EHLO smtp4-g19.free.fr" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S965641AbXA3Rjo (ORCPT ); Tue, 30 Jan 2007 12:39:44 -0500 Message-ID: <45BF8290.6010602@free.fr> Date: Tue, 30 Jan 2007 18:38:24 +0100 From: John User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.0.8) Gecko/20061108 SeaMonkey/1.0.6 MIME-Version: 1.0 To: linux-kernel@vger.kernel.org CC: tglx@timesys.com, mingo@elte.hu, johnstul@us.ibm.com, akpm@osdl.org, shill@free.fr Subject: Re: One-shot high-resolution POSIX timer periodically late References: In-Reply-To: Content-Type: multipart/mixed; boundary="------------080008000808010507000201" Sender: linux-kernel-owner@vger.kernel.org X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 15142 Lines: 455 This is a multi-part message in MIME format. --------------080008000808010507000201 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 8bit John Stultz wrote: > Also do check the -rt tree as Ingo suggested. I mis-read your earlier > email and thought you were running it. I've been pulling my hair over a related issue for the past two days. (I think I may be tickling a -hrt bug...) I'm working with 2.6.18.6 + patch-2.6.18-rt7 I've built a minimal kernel. The attached dot.config contains only the list of options that are set. I've also attached dmesg. # cat /proc/cpuinfo processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 11 model name : Intel(R) Pentium(R) III CPU - S 1266MHz stepping : 4 cpu MHz : 1266.773 cache size : 512 KB fdiv_bug : no hlt_bug : no f00f_bug : no coma_bug : no fpu : yes fpu_exception : yes cpuid level : 2 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 sep mtrr pge mca cmov pat pse36 mmx fxsr sse bogomips : 2535.13 I've set up two systems, A and B. Every millisecond, system A sends one UDP datagram containing two struct timespec: the deadline and the actual timestamp. System B blocks indefinitely waiting for packets from A. When it receives a packet, it reads several timestamps: 1. the CPU's TSC (time stamp counter) 2. clock_gettime(CLOCK_REALTIME) 3. clock_gettime(CLOCK_MONOTONIC) 4. the struct timeval provided by the kernel I then compute the differences for consecutive packets. They should all be (approximately) equal to 1 ms. I say approximately because unpredictable system latencies might introduce a small error. Also clock skew between the two systems means 1 ms on A might be seen as 0.99 ms on B. Anyway... sometimes after a few minutes, and sometimes after several hours, the one millisecond seen by A is seen as .950 ms on B, all of a sudden, for several hundred packets in a row. However the TSC indicates that 1 ms has actually gone by. For example, Packet N: timestamp 3 = 6967.391882010 timestamp 1 = 26808296 Packet N+1: timestamp 3 = 6967.392832017 timestamp 1 = 28074967 diff3 = 950007 ns diff1 = 1266671 cycles = 1 ms As far as all the timers in the system are concerned, only 950 ?s have gone by. But as far as the TSC is concerned, 1000 ?s have gone by. Logically, the TSC is right, and the other timers are wrong. I've also seen the problem go the other way, i.e. the timers think 1050 ?s have gone by instead of just 1000. However, in that case, the TSC agrees with them! This might mean that the same problem has manifested on the other system. I'll need to add code to check this condition on the sender. Have you ever seen something like this? Does the kernel ever write to the TSC? I am grasping at straws. Help :-( (I can provide my test code if it helps.) --------------080008000808010507000201 Content-Type: text/plain; name="dot.config" Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename="dot.config" CONFIG_X86_32=y CONFIG_GENERIC_TIME=y CONFIG_GENERIC_CLOCKEVENTS=y CONFIG_LOCKDEP_SUPPORT=y CONFIG_STACKTRACE_SUPPORT=y CONFIG_SEMAPHORE_SLEEPERS=y CONFIG_X86=y CONFIG_MMU=y CONFIG_GENERIC_ISA_DMA=y CONFIG_GENERIC_IOMAP=y CONFIG_GENERIC_HWEIGHT=y CONFIG_ARCH_MAY_HAVE_PC_FDC=y CONFIG_DMI=y CONFIG_DEFCONFIG_LIST="/lib/modules/$UNAME_RELEASE/.config" CONFIG_EXPERIMENTAL=y CONFIG_BROKEN_ON_SMP=y CONFIG_LOCK_KERNEL=y CONFIG_INIT_ENV_ARG_LIMIT=32 CONFIG_LOCALVERSION="" CONFIG_SYSVIPC=y CONFIG_INITRAMFS_SOURCE="" CONFIG_UID16=y CONFIG_SYSCTL=y CONFIG_KALLSYMS=y CONFIG_HOTPLUG=y CONFIG_PRINTK=y CONFIG_BUG=y CONFIG_ELF_CORE=y CONFIG_BASE_FULL=y CONFIG_FUTEX=y CONFIG_EPOLL=y CONFIG_SHMEM=y CONFIG_SLAB=y CONFIG_VM_EVENT_COUNTERS=y CONFIG_RT_MUTEXES=y CONFIG_BASE_SMALL=0 CONFIG_MODULES=y CONFIG_MODULE_UNLOAD=y CONFIG_IOSCHED_NOOP=y CONFIG_DEFAULT_NOOP=y CONFIG_DEFAULT_IOSCHED="noop" CONFIG_HIGH_RES_TIMERS=y CONFIG_X86_PC=y CONFIG_MPENTIUMIII=y CONFIG_X86_CMPXCHG=y CONFIG_X86_XADD=y CONFIG_X86_L1_CACHE_SHIFT=5 CONFIG_RWSEM_GENERIC_SPINLOCK=y CONFIG_GENERIC_CALIBRATE_DELAY=y CONFIG_X86_WP_WORKS_OK=y CONFIG_X86_INVLPG=y CONFIG_X86_BSWAP=y CONFIG_X86_POPAD_OK=y CONFIG_X86_CMPXCHG64=y CONFIG_X86_GOOD_APIC=y CONFIG_X86_INTEL_USERCOPY=y CONFIG_X86_USE_PPRO_CHECKSUM=y CONFIG_X86_TSC=y CONFIG_PREEMPT_RT=y CONFIG_PREEMPT=y CONFIG_PREEMPT_SOFTIRQS=y CONFIG_PREEMPT_HARDIRQS=y CONFIG_PREEMPT_BKL=y CONFIG_PREEMPT_RCU=y CONFIG_ASM_SEMAPHORES=y CONFIG_VM86=y CONFIG_X86_MSR=y CONFIG_X86_CPUID=y CONFIG_NOHIGHMEM=y CONFIG_PAGE_OFFSET=0xC0000000 CONFIG_ARCH_FLATMEM_ENABLE=y CONFIG_ARCH_SPARSEMEM_ENABLE=y CONFIG_ARCH_SELECT_MEMORY_MODEL=y CONFIG_SELECT_MEMORY_MODEL=y CONFIG_FLATMEM_MANUAL=y CONFIG_FLATMEM=y CONFIG_FLAT_NODE_MEM_MAP=y CONFIG_SPARSEMEM_STATIC=y CONFIG_SPLIT_PTLOCK_CPUS=4 CONFIG_MTRR=y CONFIG_REGPARM=y CONFIG_HZ_100=y CONFIG_HZ=100 CONFIG_PHYSICAL_START=0x100000 CONFIG_COMPAT_VDSO=y CONFIG_PM=y CONFIG_ACPI=y CONFIG_ACPI_BLACKLIST_YEAR=0 CONFIG_ACPI_EC=y CONFIG_ACPI_POWER=y CONFIG_ACPI_SYSTEM=y CONFIG_X86_PM_TIMER=y CONFIG_PCI=y CONFIG_PCI_GOANY=y CONFIG_PCI_BIOS=y CONFIG_PCI_DIRECT=y CONFIG_PCI_MMCONFIG=y CONFIG_ISA_DMA_API=y CONFIG_BINFMT_ELF=y CONFIG_NET=y CONFIG_NETDEBUG=y CONFIG_PACKET=y CONFIG_PACKET_MMAP=y CONFIG_UNIX=y CONFIG_INET=y CONFIG_IP_MULTICAST=y CONFIG_IP_ADVANCED_ROUTER=y CONFIG_ASK_IP_FIB_HASH=y CONFIG_IP_FIB_HASH=y CONFIG_IP_MULTIPLE_TABLES=y CONFIG_IP_ROUTE_VERBOSE=y CONFIG_INET_DIAG=y CONFIG_INET_TCP_DIAG=y CONFIG_TCP_CONG_BIC=y CONFIG_VLAN_8021Q=y CONFIG_NET_SCHED=y CONFIG_NET_SCH_CLK_GETTIMEOFDAY=y CONFIG_NET_SCH_NETEM=y CONFIG_STANDALONE=y CONFIG_PREVENT_FIRMWARE_BUILD=y CONFIG_PNP=y CONFIG_IDE=y CONFIG_BLK_DEV_IDE=y CONFIG_BLK_DEV_IDEDISK=y CONFIG_IDE_GENERIC=y CONFIG_BLK_DEV_IDEPCI=y CONFIG_IDEPCI_SHARE_IRQ=y CONFIG_BLK_DEV_GENERIC=y CONFIG_BLK_DEV_IDEDMA_PCI=y CONFIG_IDEDMA_PCI_AUTO=y CONFIG_BLK_DEV_VIA82CXXX=y CONFIG_BLK_DEV_IDEDMA=y CONFIG_IDEDMA_AUTO=y CONFIG_NETDEVICES=y CONFIG_DUMMY=y CONFIG_NET_ETHERNET=y CONFIG_MII=y CONFIG_NET_PCI=y CONFIG_EEPRO100=y CONFIG_INPUT=y CONFIG_INPUT_MOUSEDEV=y CONFIG_INPUT_MOUSEDEV_SCREEN_X=1280 CONFIG_INPUT_MOUSEDEV_SCREEN_Y=1024 CONFIG_INPUT_KEYBOARD=y CONFIG_KEYBOARD_ATKBD=y CONFIG_SERIO=y CONFIG_SERIO_I8042=y CONFIG_SERIO_LIBPS2=y CONFIG_VT=y CONFIG_VT_CONSOLE=y CONFIG_HW_CONSOLE=y CONFIG_UNIX98_PTYS=y CONFIG_LEGACY_PTYS=y CONFIG_LEGACY_PTY_COUNT=256 CONFIG_VGA_CONSOLE=y CONFIG_DUMMY_CONSOLE=y CONFIG_USB_ARCH_HAS_HCD=y CONFIG_USB_ARCH_HAS_OHCI=y CONFIG_USB_ARCH_HAS_EHCI=y CONFIG_EXT2_FS=y CONFIG_DNOTIFY=y CONFIG_PROC_FS=y CONFIG_PROC_KCORE=y CONFIG_SYSFS=y CONFIG_TMPFS=y CONFIG_RAMFS=y CONFIG_MSDOS_PARTITION=y CONFIG_PROFILE_NMI=y CONFIG_TRACE_IRQFLAGS_SUPPORT=y CONFIG_LOG_BUF_SHIFT=14 CONFIG_DEBUG_BUGVERBOSE=y CONFIG_EARLY_PRINTK=y CONFIG_DOUBLEFAULT=y CONFIG_CRC32=y CONFIG_PLIST=y CONFIG_GENERIC_HARDIRQS=y CONFIG_GENERIC_IRQ_PROBE=y CONFIG_X86_BIOS_REBOOT=y CONFIG_KTIME_SCALAR=y --------------080008000808010507000201 Content-Type: text/plain; name="dmesg" Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename="dmesg" Linux version 2.6.18.6-rt7 (john@venus) (gcc version 3.4.4) #1 PREEMPT Tue Jan 30 17:03:44 CET 2007 BIOS-provided physical RAM map: BIOS-e820: 0000000000000000 - 00000000000a0000 (usable) BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved) BIOS-e820: 0000000000100000 - 000000000fff0000 (usable) BIOS-e820: 000000000fff0000 - 000000000fff3000 (ACPI NVS) BIOS-e820: 000000000fff3000 - 0000000010000000 (ACPI data) BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved) 255MB LOWMEM available. On node 0 totalpages: 65520 DMA zone: 4096 pages, LIFO batch:0 Normal zone: 61424 pages, LIFO batch:15 DMI 2.3 present. ACPI: RSDP (v000 VIA601 ) @ 0x000f7110 ACPI: RSDT (v001 VIA601 AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x0fff3000 ACPI: FADT (v001 VIA601 AWRDACPI 0x42302e31 AWRD 0x00000000) @ 0x0fff3040 ACPI: DSDT (v001 VIA601 AWRDACPI 0x00001000 MSFT 0x0100000c) @ 0x00000000 ACPI: PM-Timer IO Port: 0x4008 Allocating PCI resources starting at 20000000 (gap: 10000000:efff0000) Detected 1266.773 MHz processor. Real-Time Preemption Support (C) 2004-2006 Ingo Molnar Built 1 zonelists. Total pages: 65520 Kernel command line: ro root=/dev/hda1 console=ttyS0,57600n8 console=tty0 panic=3 Enabling fast FPU save and restore... done. Enabling unmasked SIMD FPU exception support... done. Initializing CPU#0 WARNING: experimental RCU implementation. Clock event device pit configured with caps set: 07 PID hash table entries: 1024 (order: 10, 4096 bytes) Console: colour VGA+ 80x25 Dentry cache hash table entries: 32768 (order: 5, 131072 bytes) Inode-cache hash table entries: 16384 (order: 4, 65536 bytes) Memory: 257232k/262080k available (1476k kernel code, 4464k reserved, 444k data, 128k init, 0k highmem) Checking if this processor honours the WP bit even in supervisor mode... Ok. Calibrating delay using timer specific routine.. 2535.13 BogoMIPS (lpj=12675656) Mount-cache hash table entries: 512 CPU: After generic identify, caps: 0383f9ff 00000000 00000000 00000000 00000000 00000000 00000000 CPU: After vendor identify, caps: 0383f9ff 00000000 00000000 00000000 00000000 00000000 00000000 CPU: L1 I cache: 16K, L1 D cache: 16K CPU: L2 cache: 512K CPU: After all inits, caps: 0383f9ff 00000000 00000000 00000040 00000000 00000000 00000000 Compat vDSO mapped to ffffe000. CPU: Intel(R) Pentium(R) III CPU - S 1266MHz stepping 04 Checking 'hlt' instruction... OK. ACPI: Core revision 20060707 ACPI: setting ELCR to 0200 (from 1e20) NET: Registered protocol family 16 ACPI: bus type pci registered PCI: PCI BIOS revision 2.10 entry at 0xfb210, last bus=2 PCI: Using configuration type 1 Setting up standard PCI resources ACPI: Interpreter enabled ACPI: Using PIC for interrupt routing ACPI: PCI Root Bridge [PCI0] (0000:00) PCI: Probing PCI hardware (bus 00) ACPI: Assume root bridge [\_SB_.PCI0] bus is 0 PCI quirk: region 6000-607f claimed by vt82c686 HW-mon PCI quirk: region 5000-500f claimed by vt82c686 SMB PCI: Firmware left 0000:00:08.0 e100 interrupts enabled, disabling PCI: Firmware left 0000:00:09.0 e100 interrupts enabled, disabling PCI: Firmware left 0000:00:0a.0 e100 interrupts enabled, disabling Boot video device is 0000:00:0b.0 ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT] ACPI: PCI Interrupt Link [LNKA] (IRQs 1 3 4 5 6 7 10 *11 12 14 15) ACPI: PCI Interrupt Link [LNKB] (IRQs 1 3 4 5 6 7 10 11 *12 14 15) ACPI: PCI Interrupt Link [LNKC] (IRQs 1 3 4 5 6 7 *10 11 12 14 15) ACPI: PCI Interrupt Link [LNKD] (IRQs 1 3 4 *5 6 7 10 11 12 14 15) Linux Plug and Play Support v0.97 (c) Adam Belay PCI: Using ACPI for IRQ routing PCI: If a device doesn't work, try "pci=routeirq". If it helps, post a report PCI: Bridge: 0000:00:01.0 IO window: disabled. MEM window: disabled. PREFETCH window: disabled. PCI: Bridge: 0000:00:0d.0 IO window: disabled. MEM window: disabled. PREFETCH window: disabled. PCI: Setting latency timer of device 0000:00:01.0 to 64 NET: Registered protocol family 2 IP route cache hash table entries: 2048 (order: 1, 8192 bytes) TCP established hash table entries: 8192 (order: 6, 262144 bytes) TCP bind hash table entries: 4096 (order: 4, 114688 bytes) TCP: Hash tables configured (established 8192 bind 4096) TCP reno registered io scheduler noop registered (default) eepro100.c:v1.09j-t 9/29/99 Donald Becker http://www.scyld.com/network/eepro100.html eepro100.c: $Revision: 1.36 $ 2000/11/17 Modified by Andrey V. Savochkin and others ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 11 PCI: setting IRQ 11 as level-triggered ACPI: PCI Interrupt 0000:00:08.0[A] -> Link [LNKA] -> GSI 11 (level, low) -> IRQ 11 eth0: 0000:00:08.0, 00:30:64:02:E8:A1, IRQ 11. Board assembly 721383-016, Physical connectors present: RJ45 Primary interface chip i82555 PHY #1. General self-test: passed. Serial sub-system self-test: passed. Internal registers self-test: passed. ROM checksum self-test: passed (0x04f4518b). ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 12 PCI: setting IRQ 12 as level-triggered ACPI: PCI Interrupt 0000:00:09.0[A] -> Link [LNKB] -> GSI 12 (level, low) -> IRQ 12 eth1: 0000:00:09.0, 00:30:64:02:E8:A2, IRQ 12. Board assembly 721383-016, Physical connectors present: RJ45 Primary interface chip i82555 PHY #1. General self-test: passed. Serial sub-system self-test: passed. Internal registers self-test: passed. ROM checksum self-test: passed (0x04f4518b). ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 10 PCI: setting IRQ 10 as level-triggered ACPI: PCI Interrupt 0000:00:0a.0[A] -> Link [LNKC] -> GSI 10 (level, low) -> IRQ 10 eth2: 0000:00:0a.0, 00:30:64:02:E8:A3, IRQ 10. Board assembly 721383-016, Physical connectors present: RJ45 Primary interface chip i82555 PHY #1. General self-test: passed. Serial sub-system self-test: passed. Internal registers self-test: passed. ROM checksum self-test: passed (0x04f4518b). Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2 ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx VP_IDE: IDE controller at PCI slot 0000:00:07.1 PCI: VIA IRQ fixup for 0000:00:07.1, from 255 to 0 VP_IDE: chipset revision 6 VP_IDE: not 100% native mode: will probe irqs later VP_IDE: VIA vt82c686b (rev 40) IDE UDMA100 controller on pci0000:00:07.1 ide0: BM-DMA at 0xd000-0xd007, BIOS settings: hda:pio, hdb:pio ide1: BM-DMA at 0xd008-0xd00f, BIOS settings: hdc:pio, hdd:pio Probing IDE interface ide0... hda: PQI IDE DiskOnModule, ATA DISK drive hda: set_drive_speed_status: status=0x51 { DriveReady SeekComplete Error } hda: set_drive_speed_status: error=0x04 { DriveStatusError } hda: set_drive_speed_status: status=0x51 { DriveReady SeekComplete Error } hda: set_drive_speed_status: error=0x04 { DriveStatusError } ide0 at 0x1f0-0x1f7,0x3f6 on irq 14 Probing IDE interface ide1... Probing IDE interface ide1... hda: max request size: 128KiB hda: 128000 sectors (65 MB) w/1KiB Cache, CHS=500/8/32 hda: hda1 hda2 PNP: No PS/2 controller found. Probing ports directly. serio: i8042 AUX port at 0x60,0x64 irq 12 serio: i8042 KBD port at 0x60,0x64 irq 1 mice: PS/2 mouse device common for all mice netem: version 1.2 TCP bic registered NET: Registered protocol family 1 NET: Registered protocol family 17 802.1Q VLAN Support v1.8 Ben Greear All bugs added by David S. Miller Using IPI Shortcut mode VFS: Mounted root (ext2 filesystem) readonly. Freeing unused kernel memory: 128k freed Time: acpi_pm clocksource has been installed. Clock event device pit configured with caps set: 08 Switched to high resolution mode on CPU 0 process `syslogd' is using obsolete setsockopt SO_BSDCOMPAT --------------080008000808010507000201-- - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/