* Time went backwards 885 ms
@ 2009-03-27 9:18 Carsten Schiers
2009-03-27 20:20 ` Dan Magenheimer
0 siblings, 1 reply; 6+ messages in thread
From: Carsten Schiers @ 2009-03-27 9:18 UTC (permalink / raw)
To: xen-devel
[-- Attachment #1.1: Type: text/plain, Size: 1222 bytes --]
Dear all,
I thought this might be worth again to report:
After rebooting a 3.3.1/2.6.18.8 environment on my AMD 4050e, I received a 885ms delta just
after powernow-k8 loaded:
Mar 26 21:28:37 data kernel: powernow-k8: Found 2 AMD Athlon(tm) Dual Core Processor 4050e processors (version 2.20.00)
Mar 26 21:28:37 data kernel: powernow-k8: 0 : fid 0xd (2100 MHz), vid 0xe
Mar 26 21:28:37 data kernel: powernow-k8: 1 : fid 0xc (2000 MHz), vid 0xf
Mar 26 21:28:37 data kernel: powernow-k8: 2 : fid 0xa (1800 MHz), vid 0x11
Mar 26 21:28:37 data kernel: powernow-k8: 3 : fid 0x2 (1000 MHz), vid 0x16
Mar 26 21:28:37 data kernel: Timer ISR/1: Time went backwards: delta=-885437842 delta_cpu=6562158 shadow=11822142480 off=436198 processed=12708016520 cpu_p
rocessed=11816016520
Mar 26 21:28:37 data kernel: 0: 12704016520
Mar 26 21:28:37 data kernel: 1: 11816016520
Find full xm dmesg, xm info, and syslog of boot attached.
Otherwise, the environment is more stable; Time went backwards appear roughly every 2-3 days,
mostly when there is a 1,0->2,1GHz jump when munin asks for CPU. It is reduced in addition by a
4 sec sampling time of the ondemand govenor.
Will test 3.4 as soon as released.
BR,
Carsten.
[-- Attachment #1.2: Type: text/html, Size: 1545 bytes --]
[-- Attachment #2: syslog.txt --]
[-- Type: text/plain, Size: 30646 bytes --]
Mar 26 21:28:37 data syslogd 1.4.1#18: restart.
Mar 26 21:28:37 data kernel: klogd 1.4.1#18, log source = /proc/kmsg started.
Mar 26 21:28:37 data kernel: Bootdata ok (command line is single root=/dev/mapper/space-data_lv_root ro BOOT console=tty0 pciback.hide=(00:02.0)(00:02.1)(00:06.0)(01:07.0)(01:08.0)(01:09.0) noirqdebug nousb xencons=off)
Mar 26 21:28:37 data kernel: Linux version 2.6.18.8-xen (root@chekotey) (gcc version 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)) #1 SMP Thu Mar 5 15:41:26 CET 2009
Mar 26 21:28:37 data kernel: BIOS-provided physical RAM map:
Mar 26 21:28:37 data kernel: Xen: 0000000000000000 - 0000000010800000 (usable)
Mar 26 21:28:37 data kernel: DMI 2.4 present.
Mar 26 21:28:37 data kernel: On node 0 totalpages: 66660
Mar 26 21:28:37 data kernel: DMA zone: 4040 pages, LIFO batch:0
Mar 26 21:28:37 data kernel: DMA32 zone: 62620 pages, LIFO batch:15
Mar 26 21:28:37 data kernel: ACPI: RSDP (v000 GBT ) @ 0x00000000000f6540
Mar 26 21:28:37 data kernel: ACPI: RSDT (v001 GBT NVDAACPI 0x42302e31 NVDA 0x01010101) @ 0x00000000bfef3000
Mar 26 21:28:37 data kernel: ACPI: FADT (v001 GBT NVDAACPI 0x42302e31 NVDA 0x01010101) @ 0x00000000bfef3040
Mar 26 21:28:37 data kernel: ACPI: SSDT (v001 PTLTD POWERNOW 0x00000001 LTP 0x00000001) @ 0x00000000bfef7880
Mar 26 21:28:37 data kernel: ACPI: HPET (v001 GBT NVDAACPI 0x42302e31 NVDA 0x00000098) @ 0x00000000bfef7ac0
Mar 26 21:28:37 data kernel: ACPI: MCFG (v001 GBT NVDAACPI 0x42302e31 NVDA 0x01010101) @ 0x00000000bfef7b00
Mar 26 21:28:37 data kernel: ACPI: MADT (v001 GBT NVDAACPI 0x42302e31 NVDA 0x01010101) @ 0x00000000bfef77c0
Mar 26 21:28:37 data kernel: ACPI: DSDT (v001 GBT NVDAACPI 0x00001000 MSFT 0x03000000) @ 0x0000000000000000
Mar 26 21:28:37 data kernel: ACPI: Local APIC address 0xfee00000
Mar 26 21:28:37 data kernel: ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
Mar 26 21:28:37 data kernel: ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled)
Mar 26 21:28:37 data kernel: ACPI: LAPIC (acpi_id[0x02] lapic_id[0x02] disabled)
Mar 26 21:28:37 data kernel: ACPI: LAPIC (acpi_id[0x03] lapic_id[0x03] disabled)
Mar 26 21:28:37 data kernel: ACPI: LAPIC_NMI (acpi_id[0x00] dfl dfl lint[0x1])
Mar 26 21:28:37 data kernel: ACPI: LAPIC_NMI (acpi_id[0x01] dfl dfl lint[0x1])
Mar 26 21:28:37 data kernel: ACPI: LAPIC_NMI (acpi_id[0x02] dfl dfl lint[0x1])
Mar 26 21:28:37 data kernel: ACPI: LAPIC_NMI (acpi_id[0x03] dfl dfl lint[0x1])
Mar 26 21:28:37 data kernel: ACPI: IOAPIC (id[0x02] address[0xfec00000] gsi_base[0])
Mar 26 21:28:37 data kernel: IOAPIC[0]: apic_id 2, version 17, address 0xfec00000, GSI 0-23
Mar 26 21:28:37 data kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
Mar 26 21:28:37 data kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
Mar 26 21:28:37 data kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 14 global_irq 14 high edge)
Mar 26 21:28:37 data kernel: ACPI: IRQ0 used by override.
Mar 26 21:28:37 data kernel: ACPI: IRQ2 used by override.
Mar 26 21:28:37 data kernel: ACPI: IRQ9 used by override.
Mar 26 21:28:37 data kernel: ACPI: IRQ14 used by override.
Mar 26 21:28:37 data kernel: Setting APIC routing to xen
Mar 26 21:28:37 data kernel: Using ACPI (MADT) for SMP configuration information
Mar 26 21:28:37 data kernel: Allocating PCI resources starting at c0000000 (gap: bff00000:32100000)
Mar 26 21:28:37 data kernel: Built 1 zonelists. Total pages: 66660
Mar 26 21:28:37 data kernel: Kernel command line: single root=/dev/mapper/space-data_lv_root ro BOOT console=tty0 pciback.hide=(00:02.0)(00:02.1)(00:06.0)(01:07.0)(01:08.0)(01:09.0) noirqdebug nousb xencons=off
Mar 26 21:28:37 data kernel: IRQ lockup detection disabled
Mar 26 21:28:37 data kernel: Initializing CPU#0
Mar 26 21:28:37 data kernel: PID hash table entries: 2048 (order: 11, 16384 bytes)
Mar 26 21:28:37 data kernel: Xen reported: 2109.592 MHz processor.
Mar 26 21:28:37 data kernel: Console: colour VGA+ 80x25
Mar 26 21:28:37 data kernel: Dentry cache hash table entries: 65536 (order: 7, 524288 bytes)
Mar 26 21:28:37 data kernel: Inode-cache hash table entries: 32768 (order: 6, 262144 bytes)
Mar 26 21:28:37 data kernel: Software IO TLB enabled:
Mar 26 21:28:37 data kernel: Aperture: 64 megabytes
Mar 26 21:28:37 data kernel: Kernel range: ffff880001ae1000 - ffff880005ae1000
Mar 26 21:28:37 data kernel: Address size: 27 bits
Mar 26 21:28:37 data kernel: PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
Mar 26 21:28:37 data kernel: Memory: 170576k/270336k available (2037k kernel code, 91268k reserved, 918k data, 156k init)
Mar 26 21:28:37 data kernel: Calibrating delay using timer specific routine.. 4220.46 BogoMIPS (lpj=8440923)
Mar 26 21:28:37 data kernel: Security Framework v1.0.0 initialized
Mar 26 21:28:37 data kernel: SELinux: Disabled at boot.
Mar 26 21:28:37 data kernel: Capability LSM initialized
Mar 26 21:28:37 data kernel: Mount-cache hash table entries: 256
Mar 26 21:28:37 data kernel: CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
Mar 26 21:28:37 data kernel: CPU: L2 Cache: 512K (64 bytes/line)
Mar 26 21:28:37 data kernel: CPU: Physical Processor ID: 0
Mar 26 21:28:37 data kernel: CPU: Processor Core ID: 0
Mar 26 21:28:37 data kernel: SMP alternatives: switching to UP code
Mar 26 21:28:37 data kernel: ACPI: Core revision 20060707
Mar 26 21:28:37 data kernel: SMP alternatives: switching to SMP code
Mar 26 21:28:37 data kernel: Brought up 2 CPUs
Mar 26 21:28:37 data kernel: Initializing CPU#1
Mar 26 21:28:37 data kernel: CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
Mar 26 21:28:37 data kernel: CPU: L2 Cache: 512K (64 bytes/line)
Mar 26 21:28:37 data kernel: CPU: Physical Processor ID: 0
Mar 26 21:28:37 data kernel: CPU: Processor Core ID: 1
Mar 26 21:28:37 data kernel: migration_cost=247
Mar 26 21:28:37 data kernel: checking if image is initramfs... it is
Mar 26 21:28:37 data kernel: Freeing initrd memory: 15522k freed
Mar 26 21:28:37 data kernel: failed to set up cpufreq notifier
Mar 26 21:28:37 data kernel: NET: Registered protocol family 16
Mar 26 21:28:37 data kernel: ACPI: bus type pci registered
Mar 26 21:28:37 data kernel: PCI: Cannot map mmconfig aperture for segment 0
Mar 26 21:28:37 data kernel: PCI: Using configuration type 1
Mar 26 21:28:37 data kernel: ACPI: Interpreter enabled
Mar 26 21:28:37 data kernel: ACPI: Using IOAPIC for interrupt routing
Mar 26 21:28:37 data kernel: ACPI: PCI Root Bridge [PCI0] (0000:00)
Mar 26 21:28:37 data kernel: PCI: Probing PCI hardware (bus 00)
Mar 26 21:28:37 data kernel: Boot video device is 0000:01:06.0
Mar 26 21:28:37 data kernel: PCI: Transparent bridge - 0000:00:08.0
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.HUB0._PRT]
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LNK1] (IRQs 5 7 9 *10 11 14 15)
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LNK2] (IRQs 5 *7 9 10 11 14 15)
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LNK3] (IRQs 5 7 9 10 *11 14 15)
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LNK4] (IRQs 5 7 9 *10 11 14 15)
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LNK5] (IRQs 5 7 9 10 11 14 15) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LNK6] (IRQs 5 7 9 10 11 14 15) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LNK7] (IRQs 5 7 9 10 11 14 15) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LNK8] (IRQs 5 7 9 10 11 14 15) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LP2P] (IRQs 5 7 9 10 11 14 15) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LUBA] (IRQs 5 *7 9 10 11 14 15)
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LUB2] (IRQs *5 7 9 10 11 14 15)
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LU1B] (IRQs 5 7 9 10 11 14 15) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LU2B] (IRQs 5 7 9 10 11 14 15) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LMAC] (IRQs 5 7 9 10 11 14 *15)
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LAZA] (IRQs 5 7 9 10 11 14 15) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LPMU] (IRQs 5 7 9 10 11 14 15) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LSMB] (IRQs 5 7 9 10 *11 14 15)
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LIDE] (IRQs 5 7 9 10 11 14 15) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [LSID] (IRQs 5 7 9 10 *11 14 15)
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC1] (IRQs 16) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC2] (IRQs 17) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC3] (IRQs 18) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC4] (IRQs 19) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC5] (IRQs 16) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC6] (IRQs 16) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC7] (IRQs 16) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC8] (IRQs 16) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [AUBA] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [AUB2] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [AU1B] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [AU2B] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APCH] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APMU] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [AAZA] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APCS] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APCM] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APCZ] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APSI] (IRQs 20 21 22 23) *0, disabled.
Mar 26 21:28:37 data kernel: Linux Plug and Play Support v0.97 (c) Adam Belay
Mar 26 21:28:37 data kernel: pnp: PnP ACPI init
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0A08
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0C02
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0C02
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0200
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0103
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0B00
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0800
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0C04
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0303
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0C02
Mar 26 21:28:37 data kernel: pnp: ACPI device : hid PNP0C01
Mar 26 21:28:37 data kernel: pnp: PnP ACPI: found 11 devices
Mar 26 21:28:37 data kernel: xen_mem: Initialising balloon driver.
Mar 26 21:28:37 data kernel: usbcore: USB support disabled
Mar 26 21:28:37 data kernel: PCI: Using ACPI for IRQ routing
Mar 26 21:28:37 data kernel: PCI: If a device doesn't work, try "pci=routeirq". If it helps, post a report
Mar 26 21:28:37 data kernel: pnp: the driver 'system' has been registered
Mar 26 21:28:37 data kernel: pnp: match found with the PnP device '00:01' and the driver 'system'
Mar 26 21:28:37 data kernel: pnp: 00:01: ioport range 0x1000-0x107f could not be reserved
Mar 26 21:28:37 data kernel: pnp: 00:01: ioport range 0x1080-0x10ff has been reserved
Mar 26 21:28:37 data kernel: pnp: 00:01: ioport range 0x1400-0x147f has been reserved
Mar 26 21:28:37 data kernel: pnp: 00:01: ioport range 0x1480-0x14ff could not be reserved
Mar 26 21:28:37 data kernel: pnp: 00:01: ioport range 0x1800-0x187f has been reserved
Mar 26 21:28:37 data kernel: pnp: 00:01: ioport range 0x1880-0x18ff has been reserved
Mar 26 21:28:37 data kernel: pnp: match found with the PnP device '00:02' and the driver 'system'
Mar 26 21:28:37 data kernel: pnp: match found with the PnP device '00:09' and the driver 'system'
Mar 26 21:28:37 data kernel: pnp: match found with the PnP device '00:0a' and the driver 'system'
Mar 26 21:28:37 data kernel: pciback 0000:00:02.0: seizing device
Mar 26 21:28:37 data kernel: pciback 0000:00:02.1: seizing device
Mar 26 21:28:37 data kernel: pciback 0000:00:06.0: seizing device
Mar 26 21:28:37 data kernel: pciback 0000:01:07.0: seizing device
Mar 26 21:28:37 data kernel: pciback 0000:01:08.0: seizing device
Mar 26 21:28:37 data kernel: pciback 0000:01:09.0: seizing device
Mar 26 21:28:37 data kernel: PCI: Bridge: 0000:00:08.0
Mar 26 21:28:37 data kernel: IO window: 9000-9fff
Mar 26 21:28:37 data kernel: MEM window: f4000000-f6ffffff
Mar 26 21:28:37 data kernel: PREFETCH window: f7000000-f7ffffff
Mar 26 21:28:37 data kernel: PCI: Bridge: 0000:00:0c.0
Mar 26 21:28:37 data kernel: IO window: a000-afff
Mar 26 21:28:37 data kernel: MEM window: f8000000-f9ffffff
Mar 26 21:28:37 data kernel: PREFETCH window: c0000000-c00fffff
Mar 26 21:28:37 data kernel: PCI: Bridge: 0000:00:0e.0
Mar 26 21:28:37 data kernel: IO window: b000-bfff
Mar 26 21:28:37 data kernel: MEM window: fa000000-fbffffff
Mar 26 21:28:37 data kernel: PREFETCH window: c0100000-c01fffff
Mar 26 21:28:37 data kernel: PCI: Setting latency timer of device 0000:00:08.0 to 64
Mar 26 21:28:37 data kernel: PCI: Setting latency timer of device 0000:00:0c.0 to 64
Mar 26 21:28:37 data kernel: PCI: Setting latency timer of device 0000:00:0e.0 to 64
Mar 26 21:28:37 data kernel: NET: Registered protocol family 2
Mar 26 21:28:37 data kernel: IP route cache hash table entries: 4096 (order: 3, 32768 bytes)
Mar 26 21:28:37 data kernel: TCP established hash table entries: 16384 (order: 6, 262144 bytes)
Mar 26 21:28:37 data kernel: TCP bind hash table entries: 8192 (order: 5, 131072 bytes)
Mar 26 21:28:37 data kernel: TCP: Hash tables configured (established 16384 bind 8192)
Mar 26 21:28:37 data kernel: TCP reno registered
Mar 26 21:28:37 data kernel: audit: initializing netlink socket (disabled)
Mar 26 21:28:37 data kernel: audit(1238099278.502:1): initialized
Mar 26 21:28:37 data kernel: VFS: Disk quotas dquot_6.5.1
Mar 26 21:28:37 data kernel: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
Mar 26 21:28:37 data kernel: Initializing Cryptographic API
Mar 26 21:28:37 data kernel: io scheduler noop registered
Mar 26 21:28:37 data kernel: io scheduler anticipatory registered
Mar 26 21:28:37 data kernel: io scheduler deadline registered
Mar 26 21:28:37 data kernel: io scheduler cfq registered (default)
Mar 26 21:28:37 data kernel: PCI: Setting latency timer of device 0000:00:0c.0 to 64
Mar 26 21:28:37 data kernel: pcie_portdrv_probe->Dev[045a:10de] has invalid IRQ. Check vendor BIOS
Mar 26 21:28:37 data kernel: assign_interrupt_mode Found MSI capability
Mar 26 21:28:37 data kernel: Allocate Port Service[0000:00:0c.0:pcie00]
Mar 26 21:28:37 data kernel: PCI: Setting latency timer of device 0000:00:0e.0 to 64
Mar 26 21:28:37 data kernel: pcie_portdrv_probe->Dev[0459:10de] has invalid IRQ. Check vendor BIOS
Mar 26 21:28:37 data kernel: assign_interrupt_mode Found MSI capability
Mar 26 21:28:37 data kernel: Allocate Port Service[0000:00:0e.0:pcie00]
Mar 26 21:28:37 data kernel: Real Time Clock Driver v1.12ac
Mar 26 21:28:37 data kernel: Linux agpgart interface v0.101 (c) Dave Jones
Mar 26 21:28:37 data kernel: RAMDISK driver initialized: 16 RAM disks of 65536K size 1024 blocksize
Mar 26 21:28:37 data kernel: Event-channel device installed.
Mar 26 21:28:37 data kernel: netfront: Initialising virtual ethernet driver.
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC4] enabled at IRQ 19
Mar 26 21:28:37 data kernel: GSI 16 sharing vector 0xA0 and IRQ 16
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt 0000:01:09.0[A] -> Link [APC4] -> GSI 19 (level, low) -> IRQ 16
Mar 26 21:28:37 data kernel: ACPI: PCI interrupt for device 0000:01:09.0 disabled
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC3] enabled at IRQ 18
Mar 26 21:28:37 data kernel: GSI 17 sharing vector 0xA8 and IRQ 17
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt 0000:01:08.0[A] -> Link [APC3] -> GSI 18 (level, low) -> IRQ 17
Mar 26 21:28:37 data kernel: ACPI: PCI interrupt for device 0000:01:08.0 disabled
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC2] enabled at IRQ 17
Mar 26 21:28:37 data kernel: GSI 18 sharing vector 0xB0 and IRQ 18
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt 0000:01:07.0[A] -> Link [APC2] -> GSI 17 (level, low) -> IRQ 18
Mar 26 21:28:37 data kernel: ACPI: PCI interrupt for device 0000:01:07.0 disabled
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APCH] enabled at IRQ 23
Mar 26 21:28:37 data kernel: GSI 19 sharing vector 0xB8 and IRQ 19
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt 0000:00:06.0[A] -> Link [APCH] -> GSI 23 (level, low) -> IRQ 19
Mar 26 21:28:37 data kernel: ACPI: PCI interrupt for device 0000:00:06.0 disabled
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [AUB2] enabled at IRQ 22
Mar 26 21:28:37 data kernel: GSI 20 sharing vector 0xC0 and IRQ 20
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt 0000:00:02.1[B] -> Link [AUB2] -> GSI 22 (level, low) -> IRQ 20
Mar 26 21:28:37 data kernel: ACPI: PCI interrupt for device 0000:00:02.1 disabled
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [AUBA] enabled at IRQ 21
Mar 26 21:28:37 data kernel: GSI 21 sharing vector 0xC8 and IRQ 21
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt 0000:00:02.0[A] -> Link [AUBA] -> GSI 21 (level, low) -> IRQ 21
Mar 26 21:28:37 data kernel: ACPI: PCI interrupt for device 0000:00:02.0 disabled
Mar 26 21:28:37 data kernel: pnp: the driver 'i8042 kbd' has been registered
Mar 26 21:28:37 data kernel: pnp: match found with the PnP device '00:08' and the driver 'i8042 kbd'
Mar 26 21:28:37 data kernel: pnp: the driver 'i8042 aux' has been registered
Mar 26 21:28:37 data kernel: PNP: PS/2 Controller [PNP0303:PS2K] at 0x60,0x64 irq 1
Mar 26 21:28:37 data kernel: PNP: PS/2 controller doesn't have AUX irq; using default 12
Mar 26 21:28:37 data kernel: serio: i8042 KBD port at 0x60,0x64 irq 1
Mar 26 21:28:37 data kernel: mice: PS/2 mouse device common for all mice
Mar 26 21:28:37 data kernel: TCP bic registered
Mar 26 21:28:37 data kernel: NET: Registered protocol family 1
Mar 26 21:28:37 data kernel: NET: Registered protocol family 17
Mar 26 21:28:37 data kernel: NET: Registered protocol family 8
Mar 26 21:28:37 data kernel: NET: Registered protocol family 20
Mar 26 21:28:37 data kernel: ACPI: (supports S0 S1 S4 S5)
Mar 26 21:28:37 data kernel: Freeing unused kernel memory: 156k freed
Mar 26 21:28:37 data kernel: input: AT Translated Set 2 keyboard as /class/input/input0
Mar 26 21:28:37 data kernel: r8168 Gigabit Ethernet driver 8.011.00-NAPI loaded
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC5] enabled at IRQ 16
Mar 26 21:28:37 data kernel: GSI 22 sharing vector 0xD0 and IRQ 22
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt 0000:02:00.0[A] -> Link [APC5] -> GSI 16 (level, low) -> IRQ 22
Mar 26 21:28:37 data kernel: PCI: Setting latency timer of device 0000:02:00.0 to 64
Mar 26 21:28:37 data kernel: r8168 0000:02:00.0: no MSI. Back to INTx.
Mar 26 21:28:37 data kernel: r8168: This product is covered by one or more of the following patents: US5,307,459, US5,434,872, US5,732,094, US6,570,884, US6,115,776, and US6,327,625.
Mar 26 21:28:37 data kernel: eth0: Identified chip type is 'RTL8168B/8111B'.
Mar 26 21:28:37 data kernel: eth0: RTL8168B/8111B at 0xffffc20000004000, 00:08:54:55:1f:12, IRQ 22
Mar 26 21:28:37 data kernel: r8168 Gigabit Ethernet driver 8.011.00-NAPI loaded
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APC7] enabled at IRQ 16
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt 0000:03:00.0[A] -> Link [APC7] -> GSI 16 (level, low) -> IRQ 22
Mar 26 21:28:37 data kernel: PCI: Setting latency timer of device 0000:03:00.0 to 64
Mar 26 21:28:37 data kernel: r8168 0000:03:00.0: no MSI. Back to INTx.
Mar 26 21:28:37 data kernel: r8168: This product is covered by one or more of the following patents: US5,307,459, US5,434,872, US5,732,094, US6,570,884, US6,115,776, and US6,327,625.
Mar 26 21:28:37 data kernel: eth1: Identified chip type is 'RTL8168B/8111B'.
Mar 26 21:28:37 data kernel: eth1: RTL8168B/8111B at 0xffffc20000006000, 00:08:54:55:1f:11, IRQ 22
Mar 26 21:28:37 data kernel: ACPI Exception (acpi_processor-0721): AE_NOT_FOUND, Processor Device is not present [20060707]
Mar 26 21:28:37 data kernel: ACPI Exception (acpi_processor-0721): AE_NOT_FOUND, Processor Device is not present [20060707]
Mar 26 21:28:37 data kernel: SCSI subsystem initialized
Mar 26 21:28:37 data kernel: libata version 2.00 loaded.
Mar 26 21:28:37 data kernel: Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
Mar 26 21:28:37 data kernel: ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
Mar 26 21:28:37 data kernel: NFORCE-MCP65: IDE controller at PCI slot 0000:00:09.0
Mar 26 21:28:37 data kernel: NFORCE-MCP65: chipset revision 161
Mar 26 21:28:37 data kernel: NFORCE-MCP65: not 100%% native mode: will probe irqs later
Mar 26 21:28:37 data kernel: NFORCE-MCP65: BIOS didn't set cable bits correctly. Enabling workaround.
Mar 26 21:28:37 data kernel: NFORCE-MCP65: 0000:00:09.0 (rev a1) UDMA133 controller
Mar 26 21:28:37 data kernel: ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:DMA, hdb:DMA
Mar 26 21:28:37 data kernel: Probing IDE interface ide0...
Mar 26 21:28:37 data kernel: hda: ST3500830A, ATA DISK drive
Mar 26 21:28:37 data kernel: hdb: JLMS XJ-HD165H, ATAPI CD/DVD-ROM drive
Mar 26 21:28:37 data kernel: ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Mar 26 21:28:37 data kernel: ahci 0000:00:0a.0: version 2.0
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt Link [APSI] enabled at IRQ 20
Mar 26 21:28:37 data kernel: GSI 23 sharing vector 0xD8 and IRQ 23
Mar 26 21:28:37 data kernel: ACPI: PCI Interrupt 0000:00:0a.0[A] -> Link [APSI] -> GSI 20 (level, low) -> IRQ 23
Mar 26 21:28:37 data kernel: hda: max request size: 512KiB
Mar 26 21:28:37 data kernel: hda: Host Protected Area detected.
Mar 26 21:28:37 data kernel: ^Icurrent capacity is 976771055 sectors (500106 MB)
Mar 26 21:28:37 data kernel: ^Inative capacity is 976773168 sectors (500107 MB)
Mar 26 21:28:37 data kernel: hda: Host Protected Area disabled.
Mar 26 21:28:37 data kernel: hda: 976773168 sectors (500107 MB) w/8192KiB Cache, CHS=60801/255/63, UDMA(100)
Mar 26 21:28:37 data kernel: hda: cache flushes supported
Mar 26 21:28:37 data kernel: hda: hda1
Mar 26 21:28:37 data kernel: hdb: ATAPI 48X DVD-ROM drive, 512kB Cache, UDMA(33)
Mar 26 21:28:37 data kernel: Uniform CD-ROM driver Revision: 3.20
Mar 26 21:28:37 data kernel: PCI: Setting latency timer of device 0000:00:0a.0 to 64
Mar 26 21:28:37 data kernel: ahci 0000:00:0a.0: AHCI 0001.0100 32 slots 4 ports 3 Gbps 0xf impl SATA mode
Mar 26 21:28:37 data kernel: ahci 0000:00:0a.0: flags: 64bit ncq pm led clo pmp pio
Mar 26 21:28:37 data kernel: ata1: SATA max UDMA/133 cmd 0xFFFFC2000001C100 ctl 0x0 bmdma 0x0 irq 23
Mar 26 21:28:37 data kernel: ata2: SATA max UDMA/133 cmd 0xFFFFC2000001C180 ctl 0x0 bmdma 0x0 irq 23
Mar 26 21:28:37 data kernel: ata3: SATA max UDMA/133 cmd 0xFFFFC2000001C200 ctl 0x0 bmdma 0x0 irq 23
Mar 26 21:28:37 data kernel: ata4: SATA max UDMA/133 cmd 0xFFFFC2000001C280 ctl 0x0 bmdma 0x0 irq 23
Mar 26 21:28:37 data kernel: scsi0 : ahci
Mar 26 21:28:37 data kernel: ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Mar 26 21:28:37 data kernel: ata1.00: ATA-8, max UDMA/133, 625142448 sectors: LBA48 NCQ (depth 31/32)
Mar 26 21:28:37 data kernel: ata1.00: ata1: dev 0 multi count 16
Mar 26 21:28:37 data kernel: ata1.00: configured for UDMA/133
Mar 26 21:28:37 data kernel: scsi1 : ahci
Mar 26 21:28:37 data kernel: ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Mar 26 21:28:37 data kernel: ata2.00: ATA-7, max UDMA/133, 976773168 sectors: LBA48 NCQ (depth 31/32)
Mar 26 21:28:37 data kernel: ata2.00: ata2: dev 0 multi count 16
Mar 26 21:28:37 data kernel: ata2.00: configured for UDMA/133
Mar 26 21:28:37 data kernel: scsi2 : ahci
Mar 26 21:28:37 data kernel: ata3: SATA link down (SStatus 0 SControl 300)
Mar 26 21:28:37 data kernel: scsi3 : ahci
Mar 26 21:28:37 data kernel: ata4: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Mar 26 21:28:37 data kernel: ata4.00: ATA-7, max UDMA/133, 976773168 sectors: LBA48 NCQ (depth 31/32)
Mar 26 21:28:37 data kernel: ata4.00: ata4: dev 0 multi count 16
Mar 26 21:28:37 data kernel: ata4.00: configured for UDMA/133
Mar 26 21:28:37 data kernel: Vendor: ATA Model: WDC WD3200BEKT-0 Rev: 11.0
Mar 26 21:28:37 data kernel: Type: Direct-Access ANSI SCSI revision: 05
Mar 26 21:28:37 data kernel: Vendor: ATA Model: ST3500830AS Rev: 3.AA
Mar 26 21:28:37 data kernel: Type: Direct-Access ANSI SCSI revision: 05
Mar 26 21:28:37 data kernel: Vendor: ATA Model: ST3500830AS Rev: 3.AA
Mar 26 21:28:37 data kernel: Type: Direct-Access ANSI SCSI revision: 05
Mar 26 21:28:37 data kernel: SCSI device sda: 625142448 512-byte hdwr sectors (320073 MB)
Mar 26 21:28:37 data kernel: sda: Write Protect is off
Mar 26 21:28:37 data kernel: sda: Mode Sense: 00 3a 00 00
Mar 26 21:28:37 data kernel: SCSI device sda: drive cache: write back
Mar 26 21:28:37 data kernel: SCSI device sda: 625142448 512-byte hdwr sectors (320073 MB)
Mar 26 21:28:37 data kernel: sda: Write Protect is off
Mar 26 21:28:37 data kernel: sda: Mode Sense: 00 3a 00 00
Mar 26 21:28:37 data kernel: SCSI device sda: drive cache: write back
Mar 26 21:28:37 data kernel: sda: sda1 sda2
Mar 26 21:28:37 data kernel: sd 0:0:0:0: Attached scsi disk sda
Mar 26 21:28:37 data kernel: SCSI device sdb: 976773168 512-byte hdwr sectors (500108 MB)
Mar 26 21:28:37 data kernel: sdb: Write Protect is off
Mar 26 21:28:37 data kernel: sdb: Mode Sense: 00 3a 00 00
Mar 26 21:28:37 data kernel: SCSI device sdb: drive cache: write back
Mar 26 21:28:37 data kernel: SCSI device sdb: 976773168 512-byte hdwr sectors (500108 MB)
Mar 26 21:28:37 data kernel: sdb: Write Protect is off
Mar 26 21:28:37 data kernel: sdb: Mode Sense: 00 3a 00 00
Mar 26 21:28:37 data kernel: SCSI device sdb: drive cache: write back
Mar 26 21:28:37 data kernel: sdb: sdb1
Mar 26 21:28:37 data kernel: sd 1:0:0:0: Attached scsi disk sdb
Mar 26 21:28:37 data kernel: SCSI device sdc: 976773168 512-byte hdwr sectors (500108 MB)
Mar 26 21:28:37 data kernel: sdc: Write Protect is off
Mar 26 21:28:37 data kernel: sdc: Mode Sense: 00 3a 00 00
Mar 26 21:28:37 data kernel: SCSI device sdc: drive cache: write back
Mar 26 21:28:37 data kernel: SCSI device sdc: 976773168 512-byte hdwr sectors (500108 MB)
Mar 26 21:28:37 data kernel: sdc: Write Protect is off
Mar 26 21:28:37 data kernel: sdc: Mode Sense: 00 3a 00 00
Mar 26 21:28:37 data kernel: SCSI device sdc: drive cache: write back
Mar 26 21:28:37 data kernel: sdc: sdc1
Mar 26 21:28:37 data kernel: sd 3:0:0:0: Attached scsi disk sdc
Mar 26 21:28:37 data kernel: Probing IDE interface ide1...
Mar 26 21:28:37 data kernel: device-mapper: ioctl: 4.7.0-ioctl (2006-06-24) initialised: dm-devel@redhat.com
Mar 26 21:28:37 data kernel: Attempting manual resume
Mar 26 21:28:37 data kernel: kjournald starting. Commit interval 5 seconds
Mar 26 21:28:37 data kernel: EXT3-fs: mounted filesystem with ordered data mode.
Mar 26 21:28:37 data kernel: input: PC Speaker as /class/input/input1
Mar 26 21:28:37 data kernel: EXT3 FS on dm-0, internal journal
Mar 26 21:28:37 data kernel: loop: loaded (max 64 devices)
Mar 26 21:28:37 data kernel: powernow-k8: Found 2 AMD Athlon(tm) Dual Core Processor 4050e processors (version 2.20.00)
Mar 26 21:28:37 data kernel: powernow-k8: 0 : fid 0xd (2100 MHz), vid 0xe
Mar 26 21:28:37 data kernel: powernow-k8: 1 : fid 0xc (2000 MHz), vid 0xf
Mar 26 21:28:37 data kernel: powernow-k8: 2 : fid 0xa (1800 MHz), vid 0x11
Mar 26 21:28:37 data kernel: powernow-k8: 3 : fid 0x2 (1000 MHz), vid 0x16
Mar 26 21:28:37 data kernel: Timer ISR/1: Time went backwards: delta=-885437842 delta_cpu=6562158 shadow=11822142480 off=436198 processed=12708016520 cpu_processed=11816016520
Mar 26 21:28:37 data kernel: 0: 12704016520
Mar 26 21:28:37 data kernel: 1: 11816016520
Mar 26 21:28:37 data kernel: kjournald starting. Commit interval 5 seconds
Mar 26 21:28:37 data kernel: EXT3 FS on sda1, internal journal
Mar 26 21:28:37 data kernel: EXT3-fs: mounted filesystem with ordered data mode.
Mar 26 21:28:37 data kernel: kjournald starting. Commit interval 5 seconds
Mar 26 21:28:37 data kernel: EXT3 FS on dm-29, internal journal
Mar 26 21:28:37 data kernel: EXT3-fs: mounted filesystem with ordered data mode.
Mar 26 21:28:37 data kernel: Adding 1048568k swap on /dev/mapper/space-data_lv_swap. Priority:-1 extents:1 across:1048568k
Mar 26 21:28:37 data kernel: Bridge firewalling registered
Mar 26 21:28:37 data kernel: device eth1 entered promiscuous mode
Mar 26 21:28:37 data kernel: audit(1238099289.142:2): dev=eth1 prom=256 old_prom=0 auid=4294967295
Mar 26 21:28:37 data kernel: r8168: eth1: link up
Mar 26 21:28:37 data kernel: intern: port 1(eth1) entering learning state
Mar 26 21:28:37 data kernel: r8168: eth0: link up
Mar 26 21:28:37 data kernel: device eth0 entered promiscuous mode
Mar 26 21:28:37 data kernel: audit(1238099289.306:3): dev=eth0 prom=256 old_prom=0 auid=4294967295
Mar 26 21:28:37 data kernel: r8168: eth1: link up
Mar 26 21:28:37 data kernel: intern: topology change detected, propagating
Mar 26 21:28:37 data kernel: intern: port 1(eth1) entering forwarding state
Mar 26 21:28:37 data kernel: extern: port 1(eth0) entering learning state
Mar 26 21:28:37 data kernel: r8168: eth0: link up
Mar 26 21:28:37 data kernel: extern: topology change detected, propagating
Mar 26 21:28:37 data kernel: extern: port 1(eth0) entering forwarding state
Mar 26 21:28:37 data kernel: device wlan entered promiscuous mode
Mar 26 21:28:37 data kernel: audit(1238099291.430:4): dev=wlan prom=256 old_prom=0 auid=4294967295
Mar 26 21:28:37 data kernel: device dmz entered promiscuous mode
Mar 26 21:28:37 data kernel: audit(1238099291.506:5): dev=dmz prom=256 old_prom=0 auid=4294967295
[-- Attachment #3: xmdmesg.txt --]
[-- Type: text/plain, Size: 9700 bytes --]
__ __ _____ _____ _
\ \/ /___ _ __ |___ / |___ / / |
\ // _ \ '_ \ |_ \ |_ \ | |
/ \ __/ | | | ___) | ___) || |
/_/\_\___|_| |_| |____(_)____(_)_|
(XEN) Xen version 3.3.1 (root@space.zz) (gcc version 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)) Thu Mar 5 14:45:11 CET 2009
(XEN) Latest ChangeSet: unavailable
(XEN) Command line: single vga=text-80x25 dom0_mem=256M cpuidle cpufreq=dom0-kernel
(XEN) Video information:
(XEN) VGA is text mode 80x25, font 8x16
(XEN) VBE/DDC methods: none; EDID transfer time: 0 seconds
(XEN) EDID info not retrieved because no DDC retrieval method detected
(XEN) Disc information:
(XEN) Found 4 MBR signatures
(XEN) Found 4 EDD information structures
(XEN) Xen-e820 RAM map:
(XEN) 0000000000000000 - 000000000009f800 (usable)
(XEN) 000000000009f800 - 00000000000a0000 (reserved)
(XEN) 00000000000f0000 - 0000000000100000 (reserved)
(XEN) 0000000000100000 - 00000000bfef0000 (usable)
(XEN) 00000000bfef0000 - 00000000bfef3000 (ACPI NVS)
(XEN) 00000000bfef3000 - 00000000bff00000 (ACPI data)
(XEN) 00000000f2000000 - 00000000f4000000 (reserved)
(XEN) 00000000fec00000 - 0000000100000000 (reserved)
(XEN) 0000000100000000 - 0000000140000000 (usable)
(XEN) System RAM: 4094MB (4192828kB)
(XEN) ACPI: RSDP 000F6540, 0014 (r0 GBT )
(XEN) ACPI: RSDT BFEF3000, 0038 (r1 GBT NVDAACPI 42302E31 NVDA 1010101)
(XEN) ACPI: FACP BFEF3040, 0074 (r1 GBT NVDAACPI 42302E31 NVDA 1010101)
(XEN) ACPI: DSDT BFEF30C0, 46DC (r1 GBT NVDAACPI 1000 MSFT 3000000)
(XEN) ACPI: FACS BFEF0000, 0040
(XEN) ACPI: SSDT BFEF7880, 0206 (r1 PTLTD POWERNOW 1 LTP 1)
(XEN) ACPI: HPET BFEF7AC0, 0038 (r1 GBT NVDAACPI 42302E31 NVDA 98)
(XEN) ACPI: MCFG BFEF7B00, 003C (r1 GBT NVDAACPI 42302E31 NVDA 1010101)
(XEN) ACPI: APIC BFEF77C0, 008E (r1 GBT NVDAACPI 42302E31 NVDA 1010101)
(XEN) Xen heap: 14MB (14600kB)
(XEN) Domain heap initialised
(XEN) Processor #0 15:11 APIC version 16
(XEN) Processor #1 15:11 APIC version 16
(XEN) IOAPIC[0]: apic_id 2, version 17, address 0xfec00000, GSI 0-23
(XEN) Enabling APIC mode: Flat. Using 1 I/O APICs
(XEN) Using scheduler: SMP Credit Scheduler (credit)
(XEN) Detected 2109.616 MHz processor.
(XEN) AMD SVM: ASIDs enabled.
(XEN) HVM: SVM enabled
(XEN) CPU0: AMD K8 machine check reporting enabled.
(XEN) CPU0: AMD Athlon(tm) Dual Core Processor 4050e stepping 02
(XEN) Booting processor 1/1 eip 8c000
(XEN) AMD: Disabling C1 Clock Ramping Node #0
(XEN) AMD SVM: ASIDs enabled.
(XEN) CPU1: AMD K8 machine check reporting enabled.
(XEN) CPU1: AMD Athlon(tm) Dual Core Processor 4050e stepping 02
(XEN) Total of 2 processors activated.
(XEN) ENABLING IO-APIC IRQs
(XEN) -> Using new ACK method
(XEN) checking TSC synchronization across 2 CPUs:
(XEN) CPU#0 had -66 usecs TSC skew, fixed it up.
(XEN) CPU#1 had 66 usecs TSC skew, fixed it up.
(XEN) Platform timer is 25.000MHz HPET
(XEN) Brought up 2 CPUs
(XEN) I/O virtualisation disabled
(XEN) *** LOADING DOMAIN 0 ***
(XEN) Xen kernel: 64-bit, lsb, compat32
(XEN) Dom0 kernel: 64-bit, lsb, paddr 0xffffffff80200000 -> 0xffffffff805baf90
(XEN) PHYSICAL MEMORY ARRANGEMENT:
(XEN) Dom0 alloc.: 0000000138000000->000000013a000000 (57344 pages to be allocated)
(XEN) VIRTUAL MEMORY ARRANGEMENT:
(XEN) Loaded kernel: ffffffff80200000->ffffffff805baf90
(XEN) Init. ramdisk: ffffffff805bb000->ffffffff814e3800
(XEN) Phys-Mach map: ffffffff814e4000->ffffffff81564000
(XEN) Start info: ffffffff81564000->ffffffff815644a4
(XEN) Page tables: ffffffff81565000->ffffffff81574000
(XEN) Boot stack: ffffffff81574000->ffffffff81575000
(XEN) TOTAL: ffffffff80000000->ffffffff81800000
(XEN) ENTRY ADDRESS: ffffffff80200000
(XEN) Dom0 has maximum 2 VCPUs
(XEN) Scrubbing Free RAM: .....................................done.
(XEN) Xen trace buffers: disabled
(XEN) Std. Loglevel: Errors and warnings
(XEN) Guest Loglevel: Nothing (Rate-limited: Errors and warnings)
(XEN) Xen is relinquishing VGA console.
(XEN) *** Serial input -> DOM0 (type 'CTRL-a' three times to switch input to Xen)
(XEN) Freed 104kB init memory.
(XEN) mm.c:676:d0 Non-privileged (0) attempt to map I/O space 000fec00
(XEN) cpu0 cx acpi info:
(XEN) count = 1
(XEN) flags: bm_cntl[1], bm_chk[0], has_cst[0],
(XEN) pwr_setup_done[1], bm_rld_set[0]
(XEN) states[0]:
(XEN) reg.space_id = 0x0
(XEN) reg.bit_width = 0x0
(XEN) reg.bit_offset = 0x0
(XEN) reg.access_size = 0x0
(XEN) reg.address = 0x0
(XEN) type = 1
(XEN) latency = 0
(XEN) power = 0
(XEN) dp(@0x0000000000000000)
(XEN) ==cpu0==
(XEN) active state: C1
(XEN) max_cstate: C2
(XEN) bus master activity: 00000000
(XEN) states:
(XEN) *C1: type[C1] promotion[--] demotion[--] latency[000]
(XEN) usage[00000000] duration[0]
(XEN) cpu1 cx acpi info:
(XEN) count = 1
(XEN) flags: bm_cntl[1], bm_chk[0], has_cst[0],
(XEN) pwr_setup_done[1], bm_rld_set[0]
(XEN) states[0]:
(XEN) reg.space_id = 0x0
(XEN) reg.bit_width = 0x0
(XEN) reg.bit_offset = 0x0
(XEN) reg.access_size = 0x0
(XEN) reg.address = 0x0
(XEN) type = 1
(XEN) latency = 0
(XEN) power = 0
(XEN) dp(@0x0000000000000000)
(XEN) ==cpu1==
(XEN) active state: C1
(XEN) max_cstate: C2
(XEN) bus master activity: 00000000
(XEN) states:
(XEN) *C1: type[C1] promotion[--] demotion[--] latency[000]
(XEN) usage[00000000] duration[0]
(XEN) cpu2 cx acpi info:
(XEN) count = 1
(XEN) flags: bm_cntl[1], bm_chk[0], has_cst[0],
(XEN) pwr_setup_done[1], bm_rld_set[0]
(XEN) states[0]:
(XEN) reg.space_id = 0x0
(XEN) reg.bit_width = 0x0
(XEN) reg.bit_offset = 0x0
(XEN) reg.access_size = 0x0
(XEN) reg.address = 0x0
(XEN) type = 1
(XEN) latency = 0
(XEN) power = 0
(XEN) dp(@0x0000000000000000)
(XEN) no cpu_id for acpi_id 2
(XEN) cpu3 cx acpi info:
(XEN) count = 1
(XEN) flags: bm_cntl[1], bm_chk[0], has_cst[0],
(XEN) pwr_setup_done[1], bm_rld_set[0]
(XEN) states[0]:
(XEN) reg.space_id = 0x0
(XEN) reg.bit_width = 0x0
(XEN) reg.bit_offset = 0x0
(XEN) reg.access_size = 0x0
(XEN) reg.address = 0x0
(XEN) type = 1
(XEN) latency = 0
(XEN) power = 0
(XEN) dp(@0x0000000000000000)
(XEN) no cpu_id for acpi_id 3
(XEN) 'h' pressed -> showing installed handlers
(XEN) key '%' (ascii '25') => Trap to xendbg
(XEN) key '0' (ascii '30') => dump Dom0 registers
(XEN) key 'C' (ascii '43') => trigger a crashdump
(XEN) key 'H' (ascii '48') => dump heap info
(XEN) key 'N' (ascii '4e') => NMI statistics
(XEN) key 'Q' (ascii '51') => dump PCI devices
(XEN) key 'R' (ascii '52') => reboot machine
(XEN) key 'a' (ascii '61') => dump timer queues
(XEN) key 'c' (ascii '63') => dump cx structures
(XEN) key 'd' (ascii '64') => dump registers
(XEN) key 'h' (ascii '68') => show this message
(XEN) key 'i' (ascii '69') => dump interrupt bindings
(XEN) key 'm' (ascii '6d') => memory info
(XEN) key 'n' (ascii '6e') => trigger an NMI
(XEN) key 'q' (ascii '71') => dump domain (and guest debug) info
(XEN) key 'r' (ascii '72') => dump run queues
(XEN) key 't' (ascii '74') => display multi-cpu clock info
(XEN) key 'u' (ascii '75') => dump numa info
(XEN) key 'v' (ascii '76') => dump AMD-V VMCBs
(XEN) key 'z' (ascii '7a') => print ioapic info
(XEN) Scheduler: SMP Credit Scheduler (credit)
(XEN) info:
(XEN) ncpus = 2
(XEN) master = 0
(XEN) credit = 600
(XEN) credit balance = 500
(XEN) weight = 512
(XEN) runq_sort = 499306
(XEN) default-weight = 256
(XEN) msecs per tick = 10ms
(XEN) credits per tick = 100
(XEN) ticks per tslice = 3
(XEN) ticks per acct = 3
(XEN) idlers: 0x1
(XEN) stats:
(XEN) schedule = 102659310
(XEN) acct_run = 499306
(XEN) acct_no_work = 999646
(XEN) acct_balance = 5383
(XEN) acct_reorder = 811
(XEN) acct_min_credit = 1102
(XEN) acct_vcpu_active = 250801
(XEN) acct_vcpu_idle = 250799
(XEN) vcpu_sleep = 78
(XEN) vcpu_wake_running = 93889
(XEN) vcpu_wake_onrunq = 645
(XEN) vcpu_wake_runnable = 51795644
(XEN) vcpu_wake_not_runnable = 0
(XEN) vcpu_park = 0
(XEN) vcpu_unpark = 0
(XEN) tickle_local_idler = 49084545
(XEN) tickle_local_over = 376143
(XEN) tickle_local_under = 553102
(XEN) tickle_local_other = 0
(XEN) tickle_idlers_none = 1481873
(XEN) tickle_idlers_some = 1227646
(XEN) load_balance_idle = 50633061
(XEN) load_balance_over = 495630
(XEN) load_balance_other = 0
(XEN) steal_trylock_failed = 138444
(XEN) steal_peer_idle = 10773774
(XEN) migrate_queued = 803248
(XEN) migrate_running = 0
(XEN) dom_init = 9
(XEN) dom_destroy = 0
(XEN) vcpu_init = 13
(XEN) vcpu_destroy = 0
(XEN) active vcpus:
(XEN) 1: [1.0] pri=-1 flags=0 cpu=1 credit=200 [w=256] (200+300) {a/i=24396/24395 m=217104+0}
(XEN) 2: [0.0] pri=0 flags=0 cpu=0 credit=300 [w=256] (300+300) {a/i=38979/38978 m=0+0}
(XEN) NOW=0x000028E732CAC5E4
(XEN) CPU[00] sort=499306, sibling=0x1, core=0x3
(XEN) run: [32767.0] pri=-64 flags=0 cpu=0
(XEN) CPU[01] sort=499306, sibling=0x2, core=0x3
(XEN) run: [0.1] pri=0 flags=0 cpu=1 credit=0 [w=256] (0+300) {a/i=14020/14020 m=0+0}
(XEN) 1: [32767.1] pri=-64 flags=0 cpu=1
[-- Attachment #4: xminfo.txt --]
[-- Type: text/plain, Size: 1116 bytes --]
host : data
release : 2.6.18.8-xen
version : #1 SMP Thu Mar 5 15:41:26 CET 2009
machine : x86_64
nr_cpus : 2
nr_nodes : 1
cores_per_socket : 2
threads_per_core : 1
cpu_mhz : 2109
hw_caps : 178bf3ff:ebd3fbff:00000000:00000010:00002001:00000000:0000011f:00000000
virt_caps : hvm
total_memory : 4094
free_memory : 7
node_to_cpu : node0:0-1
node_to_memory : node0:7
xen_major : 3
xen_minor : 3
xen_extra : .1
xen_caps : xen-3.0-x86_64 xen-3.0-x86_32p hvm-3.0-x86_32 hvm-3.0-x86_32p hvm-3.0-x86_64
xen_scheduler : credit
xen_pagesize : 4096
platform_params : virt_start=0xffff800000000000
xen_changeset : unavailable
cc_compiler : gcc version 4.1.2 20061115 (prerelease) (Debian 4.1.1-21)
cc_compile_by : root
cc_compile_domain : space.zz
cc_compile_date : Thu Mar 5 14:45:11 CET 2009
xend_config_format : 4
[-- Attachment #5: Type: text/plain, Size: 138 bytes --]
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel
^ permalink raw reply [flat|nested] 6+ messages in thread* RE: Time went backwards 885 ms
2009-03-27 9:18 Time went backwards 885 ms Carsten Schiers
@ 2009-03-27 20:20 ` Dan Magenheimer
2009-03-28 9:52 ` AW: " Carsten Schiers
0 siblings, 1 reply; 6+ messages in thread
From: Dan Magenheimer @ 2009-03-27 20:20 UTC (permalink / raw)
To: Carsten Schiers, xen-devel
Two possibilities... many power management features
have gone into Xen and there are many bug fixes post-3.3
to improve time sync in the presence of power management.
However if power management is NOT happening on your system,
it's possible that your processors have bad TSC skew
that Xen's TSC synchronization mechanism is unable to
handle. (This seems unlikely with a dual core... AMD
might have information otherwise.)
A nice feature that went into Xen 3.3 is the ability to
measure the skew between physical processors. The
"xm debug-key t" takes only one sample, but it can
be repeated many times and will retain max and avg
for all of the samples.
Can you do:
# for j in $(seq -w 10000); do xm debug-key t; done
in dom0, then send the output from "xm dmesg | tail"
If you can do this both with Xen 3.3 and 3.4 (when it
is released, or xen-unstable now), that would be great!
-----Original Message-----
From: Carsten Schiers [mailto:carsten@schiers.de]
Sent: Friday, March 27, 2009 3:19 AM
To: xen-devel
Subject: [Xen-devel] Time went backwards 885 ms
Dear all,
I thought this might be worth again to report:
After rebooting a 3.3.1/2.6.18.8 environment on my AMD 4050e, I received a 885ms delta just
after powernow-k8 loaded:
Mar 26 21:28:37 data kernel: powernow-k8: Found 2 AMD Athlon(tm) Dual Core Processor 4050e processors (version 2.20.00)
Mar 26 21:28:37 data kernel: powernow-k8: 0 : fid 0xd (2100 MHz), vid 0xe
Mar 26 21:28:37 data kernel: powernow-k8: 1 : fid 0xc (2000 MHz), vid 0xf
Mar 26 21:28:37 data kernel: powernow-k8: 2 : fid 0xa (1800 MHz), vid 0x11
Mar 26 21:28:37 data kernel: powernow-k8: 3 : fid 0x2 (1000 MHz), vid 0x16
Mar 26 21:28:37 data kernel: Timer ISR/1: Time went backwards: delta=-885437842 delta_cpu=6562158 shadow=11822142480 off=436198 processed=12708016520 cpu_p
rocessed=11816016520
Mar 26 21:28:37 data kernel: 0: 12704016520
Mar 26 21:28:37 data kernel: 1: 11816016520
Find full xm dmesg, xm info, and syslog of boot attached.
Otherwise, the environment is more stable; Time went backwards appear roughly every 2-3 days,
mostly when there is a 1,0->2,1GHz jump when munin asks for CPU. It is reduced in addition by a
4 sec sampling time of the ondemand govenor.
Will test 3.4 as soon as released.
BR,
Carsten.
^ permalink raw reply [flat|nested] 6+ messages in thread
* AW: RE: Time went backwards 885 ms
2009-03-27 20:20 ` Dan Magenheimer
@ 2009-03-28 9:52 ` Carsten Schiers
2009-03-28 10:22 ` Carsten Schiers
0 siblings, 1 reply; 6+ messages in thread
From: Carsten Schiers @ 2009-03-28 9:52 UTC (permalink / raw)
To: dan.magenheimer, xen-devel
Oh, I didn't know that...
I started to do so. But not all lines will show up in xm dmesg. Is there
any trick to have a bigger buffer to capture it or are only the last
lines
of interest?
BR,
Carsten.
-----Ursprüngliche Nachricht-----
Von: Dan Magenheimer [mailto:dan.magenheimer@oracle.com]
Gesendet: Freitag, 27. März 2009 21:20
An: Carsten Schiers; xen-devel
Betreff: RE: [Xen-devel] Time went backwards 885 ms
Two possibilities... many power management features
have gone into Xen and there are many bug fixes post-3.3
to improve time sync in the presence of power management.
However if power management is NOT happening on your system,
it's possible that your processors have bad TSC skew
that Xen's TSC synchronization mechanism is unable to
handle. (This seems unlikely with a dual core... AMD
might have information otherwise.)
A nice feature that went into Xen 3.3 is the ability to
measure the skew between physical processors. The
"xm debug-key t" takes only one sample, but it can
be repeated many times and will retain max and avg
for all of the samples.
Can you do:
# for j in $(seq -w 10000); do xm debug-key t; done
in dom0, then send the output from "xm dmesg | tail"
If you can do this both with Xen 3.3 and 3.4 (when it
is released, or xen-unstable now), that would be great!
-----Original Message-----
From: Carsten Schiers [mailto:carsten@schiers.de]
Sent: Friday, March 27, 2009 3:19 AM
To: xen-devel
Subject: [Xen-devel] Time went backwards 885 ms
Dear all,
I thought this might be worth again to report:
After rebooting a 3.3.1/2.6.18.8 environment on my AMD 4050e, I received
a 885ms delta just
after powernow-k8 loaded:
Mar 26 21:28:37 data kernel: powernow-k8: Found 2 AMD Athlon(tm) Dual
Core Processor 4050e processors (version 2.20.00)
Mar 26 21:28:37 data kernel: powernow-k8: 0 : fid 0xd (2100 MHz), vid
0xe
Mar 26 21:28:37 data kernel: powernow-k8: 1 : fid 0xc (2000 MHz), vid
0xf
Mar 26 21:28:37 data kernel: powernow-k8: 2 : fid 0xa (1800 MHz), vid
0x11
Mar 26 21:28:37 data kernel: powernow-k8: 3 : fid 0x2 (1000 MHz), vid
0x16
Mar 26 21:28:37 data kernel: Timer ISR/1: Time went backwards:
delta=-885437842 delta_cpu=6562158 shadow=11822142480 off=436198
processed=12708016520 cpu_p
rocessed=11816016520
Mar 26 21:28:37 data kernel: 0: 12704016520
Mar 26 21:28:37 data kernel: 1: 11816016520
Find full xm dmesg, xm info, and syslog of boot attached.
Otherwise, the environment is more stable; Time went backwards appear
roughly every 2-3 days,
mostly when there is a 1,0->2,1GHz jump when munin asks for CPU. It is
reduced in addition by a
4 sec sampling time of the ondemand govenor.
Will test 3.4 as soon as released.
BR,
Carsten.
^ permalink raw reply [flat|nested] 6+ messages in thread
* AW: RE: Time went backwards 885 ms
2009-03-28 9:52 ` AW: " Carsten Schiers
@ 2009-03-28 10:22 ` Carsten Schiers
2009-03-28 10:33 ` Carsten Schiers
0 siblings, 1 reply; 6+ messages in thread
From: Carsten Schiers @ 2009-03-28 10:22 UTC (permalink / raw)
To: dan.magenheimer, xen-devel
Here e.g. the last entries for Xen 3.3.1:
(XEN) Synced cycles skew: max=1142 avg=315 samples=12670 current=256
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12671
current=36ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12671 current=449
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12672
current=60ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12672 current=257
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12673
current=19ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12673 current=382
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12674
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12674 current=48
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12675
current=54ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12675 current=382
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12676
current=16ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12676 current=445
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12677
current=49ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12677 current=508
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12678
current=90ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12678 current=62
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12679
current=14ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12679 current=292
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12680
current=21ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12680 current=193
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12681
current=88ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12681 current=143
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12682
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12682 current=382
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12683
current=1ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12683 current=33
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12684
current=18ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12684 current=4
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12685
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12685 current=370
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12686
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12686 current=48
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12687
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12687 current=48
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12688
current=44ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12688 current=366
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12689
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12689 current=369
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12690
current=75ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12690 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12691
current=31ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12691 current=78
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12692
current=124ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12692 current=289
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12693
current=80ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12693 current=330
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12694
current=22ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12694 current=256
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12695
current=79ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12695 current=373
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12696
current=97ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12696 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12697
current=119ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12697 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12698
current=140ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12698 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12699
current=164ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12699 current=334
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12700
current=160ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12700 current=370
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12701
current=122ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12701 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12702
current=74ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12702 current=175
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12703
current=65ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12703 current=102
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12704
current=89ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12704 current=62
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12705
current=85ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12705 current=116
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12706
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12706 current=188
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12707
current=10ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12707 current=31
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12708
current=57ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12708 current=65
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12709
current=54ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12709 current=295
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12710
current=119ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12710 current=77
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12711
current=108ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12711 current=47
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12712
current=78ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12712 current=52
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12713
current=57ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12713 current=49
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12714
current=26ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12714 current=42
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12715
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12715 current=62
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12716
current=9ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12716 current=53
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12717
current=10ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12717 current=52
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12718
current=1ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12718 current=33
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12719
current=109ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12719 current=175
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12720
current=0ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12720 current=36
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12721
current=17ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12721 current=256
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12722
current=85ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12722 current=422
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12723
current=92ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12723 current=492
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12724
current=50ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12724 current=387
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12725
current=94ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12725 current=490
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12726
current=43ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12726 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12727
current=60ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12727 current=57
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12728
current=48ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12728 current=287
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12729
current=57ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12729 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12730
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12730 current=251
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12731
current=90ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12731 current=169
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12732
current=38ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12732 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12733
current=189ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12733 current=345
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12734
current=6ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12734 current=256
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12735
current=52ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12735 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12736
current=46ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12736 current=294
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12737
current=90ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12737 current=465
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12738
current=50ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12738 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12739
current=51ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12739 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12740
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12740 current=330
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12741
current=62ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12741 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12742
current=47ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12742 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12743
current=4ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12743 current=292
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12744
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12744 current=330
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12745
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12745 current=48
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12746
current=87ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12746 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12747
current=93ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12747 current=328
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12748
current=28ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12748 current=98
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12749
current=29ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12749 current=102
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12750
current=112ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12750 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12751
current=138ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12751 current=372
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12752
current=108ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12752 current=339
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12753
current=85ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12753 current=335
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12754
current=61ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12754 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12755
current=18ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12755 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12756
current=3ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12756 current=170
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12757
current=122ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12757 current=22
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12758
current=150ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12758 current=285
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12759
current=269ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12759 current=408
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12760
current=246ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12760 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12761
current=179ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12761 current=52
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12762
current=165ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12762 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12763
current=149ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12763 current=490
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12764
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12764 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12765
current=60ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12765 current=193
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12766
current=33ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12766 current=545
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12767
current=108ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12767 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12768
current=25ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12768 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12769
current=51ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12769 current=285
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12770
current=88ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12770 current=103
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12771
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12771 current=373
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12772
current=94ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12772 current=134
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12773
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12773 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12774
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12774 current=217
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12775
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12775 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12776
current=21ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12776 current=297
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12777
current=11ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12777 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12778
current=20ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12778 current=47
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12779
current=15ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12779 current=48
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12780
current=9ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12780 current=251
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12781
current=48ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12781 current=79
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12782
current=70ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12782 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12783
current=65ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12783 current=330
-----Ursprüngliche Nachricht-----
Von: Carsten Schiers
Gesendet: Samstag, 28. März 2009 10:53
An: dan.magenheimer; xen-devel
Betreff: AW: RE: [Xen-devel] Time went backwards 885 ms
Oh, I didn't know that...
I started to do so. But not all lines will show up in xm dmesg. Is there
any trick to have a bigger buffer to capture it or are only the last
lines
of interest?
BR,
Carsten.
-----Ursprüngliche Nachricht-----
Von: Dan Magenheimer [mailto:dan.magenheimer@oracle.com]
Gesendet: Freitag, 27. März 2009 21:20
An: Carsten Schiers; xen-devel
Betreff: RE: [Xen-devel] Time went backwards 885 ms
Two possibilities... many power management features
have gone into Xen and there are many bug fixes post-3.3
to improve time sync in the presence of power management.
However if power management is NOT happening on your system,
it's possible that your processors have bad TSC skew
that Xen's TSC synchronization mechanism is unable to
handle. (This seems unlikely with a dual core... AMD
might have information otherwise.)
A nice feature that went into Xen 3.3 is the ability to
measure the skew between physical processors. The
"xm debug-key t" takes only one sample, but it can
be repeated many times and will retain max and avg
for all of the samples.
Can you do:
# for j in $(seq -w 10000); do xm debug-key t; done
in dom0, then send the output from "xm dmesg | tail"
If you can do this both with Xen 3.3 and 3.4 (when it
is released, or xen-unstable now), that would be great!
-----Original Message-----
From: Carsten Schiers [mailto:carsten@schiers.de]
Sent: Friday, March 27, 2009 3:19 AM
To: xen-devel
Subject: [Xen-devel] Time went backwards 885 ms
Dear all,
I thought this might be worth again to report:
After rebooting a 3.3.1/2.6.18.8 environment on my AMD 4050e, I received
a 885ms delta just
after powernow-k8 loaded:
Mar 26 21:28:37 data kernel: powernow-k8: Found 2 AMD Athlon(tm) Dual
Core Processor 4050e processors (version 2.20.00)
Mar 26 21:28:37 data kernel: powernow-k8: 0 : fid 0xd (2100 MHz), vid
0xe
Mar 26 21:28:37 data kernel: powernow-k8: 1 : fid 0xc (2000 MHz), vid
0xf
Mar 26 21:28:37 data kernel: powernow-k8: 2 : fid 0xa (1800 MHz), vid
0x11
Mar 26 21:28:37 data kernel: powernow-k8: 3 : fid 0x2 (1000 MHz), vid
0x16
Mar 26 21:28:37 data kernel: Timer ISR/1: Time went backwards:
delta=-885437842 delta_cpu=6562158 shadow=11822142480 off=436198
processed=12708016520 cpu_p
rocessed=11816016520
Mar 26 21:28:37 data kernel: 0: 12704016520
Mar 26 21:28:37 data kernel: 1: 11816016520
Find full xm dmesg, xm info, and syslog of boot attached.
Otherwise, the environment is more stable; Time went backwards appear
roughly every 2-3 days,
mostly when there is a 1,0->2,1GHz jump when munin asks for CPU. It is
reduced in addition by a
4 sec sampling time of the ondemand govenor.
Will test 3.4 as soon as released.
BR,
Carsten.
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel
^ permalink raw reply [flat|nested] 6+ messages in thread
* AW: RE: Time went backwards 885 ms
2009-03-28 10:22 ` Carsten Schiers
@ 2009-03-28 10:33 ` Carsten Schiers
2009-03-28 13:38 ` Dan Magenheimer
0 siblings, 1 reply; 6+ messages in thread
From: Carsten Schiers @ 2009-03-28 10:33 UTC (permalink / raw)
To: dan.magenheimer, xen-devel
Ups sorry, missed the tail I guess you are only interested in the max
values...
BTW: during the measurement, there was a Time went Backwards in log:
Mar 28 10:47:15 data kernel: Timer ISR/0: Time went backwards:
delta=-67288961 delta_cpu=72711039 shadow=134369155097800 off=65631400
processed=134369288016520 cpu_processed=134369148016520
Mar 28 10:47:15 data kernel: 0: 134369148016520
Mar 28 10:47:15 data kernel: 1: 134369288016520
Will try to check on unstable soon...
BR,
Carsten.
-----Ursprüngliche Nachricht-----
Von: Carsten Schiers
Gesendet: Samstag, 28. März 2009 11:23
An: dan.magenheimer; xen-devel
Betreff: AW: RE: [Xen-devel] Time went backwards 885 ms
Here e.g. the last entries for Xen 3.3.1:
(XEN) Synced cycles skew: max=1142 avg=315 samples=12670 current=256
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12671
current=36ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12671 current=449
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12672
current=60ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12672 current=257
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12673
current=19ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12673 current=382
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12674
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12674 current=48
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12675
current=54ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12675 current=382
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12676
current=16ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12676 current=445
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12677
current=49ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12677 current=508
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12678
current=90ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12678 current=62
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12679
current=14ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12679 current=292
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12680
current=21ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12680 current=193
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12681
current=88ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12681 current=143
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12682
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12682 current=382
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12683
current=1ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12683 current=33
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12684
current=18ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12684 current=4
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12685
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12685 current=370
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12686
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12686 current=48
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12687
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12687 current=48
(XEN) Synced stime skew: max=297847ns avg=451ns samples=12688
current=44ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12688 current=366
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12689
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12689 current=369
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12690
current=75ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12690 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12691
current=31ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12691 current=78
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12692
current=124ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12692 current=289
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12693
current=80ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12693 current=330
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12694
current=22ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12694 current=256
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12695
current=79ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12695 current=373
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12696
current=97ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12696 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12697
current=119ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12697 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12698
current=140ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12698 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12699
current=164ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12699 current=334
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12700
current=160ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12700 current=370
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12701
current=122ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12701 current=382
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12702
current=74ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12702 current=175
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12703
current=65ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12703 current=102
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12704
current=89ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12704 current=62
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12705
current=85ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12705 current=116
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12706
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12706 current=188
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12707
current=10ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12707 current=31
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12708
current=57ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12708 current=65
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12709
current=54ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12709 current=295
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12710
current=119ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12710 current=77
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12711
current=108ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12711 current=47
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12712
current=78ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12712 current=52
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12713
current=57ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12713 current=49
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12714
current=26ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12714 current=42
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12715
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12715 current=62
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12716
current=9ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12716 current=53
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12717
current=10ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12717 current=52
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12718
current=1ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12718 current=33
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12719
current=109ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12719 current=175
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12720
current=0ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12720 current=36
(XEN) Synced stime skew: max=297847ns avg=450ns samples=12721
current=17ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12721 current=256
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12722
current=85ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12722 current=422
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12723
current=92ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12723 current=492
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12724
current=50ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12724 current=387
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12725
current=94ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12725 current=490
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12726
current=43ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12726 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12727
current=60ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12727 current=57
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12728
current=48ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12728 current=287
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12729
current=57ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12729 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12730
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12730 current=251
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12731
current=90ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12731 current=169
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12732
current=38ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12732 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12733
current=189ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12733 current=345
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12734
current=6ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12734 current=256
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12735
current=52ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12735 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12736
current=46ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12736 current=294
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12737
current=90ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12737 current=465
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12738
current=50ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12738 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12739
current=51ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12739 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12740
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12740 current=330
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12741
current=62ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12741 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12742
current=47ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12742 current=62
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12743
current=4ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12743 current=292
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12744
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12744 current=330
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12745
current=7ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12745 current=48
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12746
current=87ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12746 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12747
current=93ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12747 current=328
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12748
current=28ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12748 current=98
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12749
current=29ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12749 current=102
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12750
current=112ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12750 current=382
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12751
current=138ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12751 current=372
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12752
current=108ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12752 current=339
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12753
current=85ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12753 current=335
(XEN) Synced stime skew: max=297847ns avg=449ns samples=12754
current=61ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12754 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12755
current=18ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12755 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12756
current=3ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12756 current=170
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12757
current=122ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12757 current=22
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12758
current=150ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12758 current=285
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12759
current=269ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12759 current=408
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12760
current=246ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12760 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12761
current=179ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12761 current=52
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12762
current=165ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12762 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12763
current=149ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12763 current=490
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12764
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12764 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12765
current=60ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12765 current=193
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12766
current=33ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12766 current=545
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12767
current=108ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12767 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12768
current=25ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12768 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12769
current=51ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12769 current=285
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12770
current=88ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12770 current=103
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12771
current=56ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12771 current=373
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12772
current=94ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12772 current=134
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12773
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12773 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12774
current=5ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12774 current=217
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12775
current=53ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12775 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12776
current=21ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12776 current=297
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12777
current=11ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12777 current=256
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12778
current=20ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12778 current=47
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12779
current=15ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12779 current=48
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12780
current=9ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12780 current=251
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12781
current=48ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12781 current=79
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12782
current=70ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12782 current=382
(XEN) Synced stime skew: max=297847ns avg=448ns samples=12783
current=65ns
(XEN) Synced cycles skew: max=1142 avg=315 samples=12783 current=330
-----Ursprüngliche Nachricht-----
Von: Carsten Schiers
Gesendet: Samstag, 28. März 2009 10:53
An: dan.magenheimer; xen-devel
Betreff: AW: RE: [Xen-devel] Time went backwards 885 ms
Oh, I didn't know that...
I started to do so. But not all lines will show up in xm dmesg. Is there
any trick to have a bigger buffer to capture it or are only the last
lines
of interest?
BR,
Carsten.
-----Ursprüngliche Nachricht-----
Von: Dan Magenheimer [mailto:dan.magenheimer@oracle.com]
Gesendet: Freitag, 27. März 2009 21:20
An: Carsten Schiers; xen-devel
Betreff: RE: [Xen-devel] Time went backwards 885 ms
Two possibilities... many power management features
have gone into Xen and there are many bug fixes post-3.3
to improve time sync in the presence of power management.
However if power management is NOT happening on your system,
it's possible that your processors have bad TSC skew
that Xen's TSC synchronization mechanism is unable to
handle. (This seems unlikely with a dual core... AMD
might have information otherwise.)
A nice feature that went into Xen 3.3 is the ability to
measure the skew between physical processors. The
"xm debug-key t" takes only one sample, but it can
be repeated many times and will retain max and avg
for all of the samples.
Can you do:
# for j in $(seq -w 10000); do xm debug-key t; done
in dom0, then send the output from "xm dmesg | tail"
If you can do this both with Xen 3.3 and 3.4 (when it
is released, or xen-unstable now), that would be great!
-----Original Message-----
From: Carsten Schiers [mailto:carsten@schiers.de]
Sent: Friday, March 27, 2009 3:19 AM
To: xen-devel
Subject: [Xen-devel] Time went backwards 885 ms
Dear all,
I thought this might be worth again to report:
After rebooting a 3.3.1/2.6.18.8 environment on my AMD 4050e, I received
a 885ms delta just
after powernow-k8 loaded:
Mar 26 21:28:37 data kernel: powernow-k8: Found 2 AMD Athlon(tm) Dual
Core Processor 4050e processors (version 2.20.00)
Mar 26 21:28:37 data kernel: powernow-k8: 0 : fid 0xd (2100 MHz), vid
0xe
Mar 26 21:28:37 data kernel: powernow-k8: 1 : fid 0xc (2000 MHz), vid
0xf
Mar 26 21:28:37 data kernel: powernow-k8: 2 : fid 0xa (1800 MHz), vid
0x11
Mar 26 21:28:37 data kernel: powernow-k8: 3 : fid 0x2 (1000 MHz), vid
0x16
Mar 26 21:28:37 data kernel: Timer ISR/1: Time went backwards:
delta=-885437842 delta_cpu=6562158 shadow=11822142480 off=436198
processed=12708016520 cpu_p
rocessed=11816016520
Mar 26 21:28:37 data kernel: 0: 12704016520
Mar 26 21:28:37 data kernel: 1: 11816016520
Find full xm dmesg, xm info, and syslog of boot attached.
Otherwise, the environment is more stable; Time went backwards appear
roughly every 2-3 days,
mostly when there is a 1,0->2,1GHz jump when munin asks for CPU. It is
reduced in addition by a
4 sec sampling time of the ondemand govenor.
Will test 3.4 as soon as released.
BR,
Carsten.
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel
^ permalink raw reply [flat|nested] 6+ messages in thread
* RE: AW: RE: Time went backwards 885 ms
2009-03-28 10:33 ` Carsten Schiers
@ 2009-03-28 13:38 ` Dan Magenheimer
0 siblings, 0 replies; 6+ messages in thread
From: Dan Magenheimer @ 2009-03-28 13:38 UTC (permalink / raw)
To: Carsten Schiers, xen-devel
The fact that max cycles skew is so much smaller than max
stime (xen system time) skew leads me to believe that this
is a power management problem, and there's a good chance
it might be fixed already in xen-unstable (soon to be 3.4).
> -----Original Message-----
> From: Carsten Schiers [mailto:carsten@schiers.de]
> Sent: Saturday, March 28, 2009 4:34 AM
> To: Dan Magenheimer; xen-devel
> Subject: AW: RE: [Xen-devel] Time went backwards 885 ms
>
>
> Ups sorry, missed the tail I guess you are only interested in the max
> values...
>
> BTW: during the measurement, there was a Time went Backwards in log:
>
> Mar 28 10:47:15 data kernel: Timer ISR/0: Time went backwards:
> delta=-67288961 delta_cpu=72711039 shadow=134369155097800
> off=65631400
> processed=134369288016520 cpu_processed=134369148016520
> Mar 28 10:47:15 data kernel: 0: 134369148016520
> Mar 28 10:47:15 data kernel: 1: 134369288016520
>
> Will try to check on unstable soon...
>
> BR,
> Carsten.
>
> -----Ursprüngliche Nachricht-----
> Von: Carsten Schiers
> Gesendet: Samstag, 28. März 2009 11:23
> An: dan.magenheimer; xen-devel
> Betreff: AW: RE: [Xen-devel] Time went backwards 885 ms
>
> Here e.g. the last entries for Xen 3.3.1:
>
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12670 current=256
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12671
> current=36ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12671 current=449
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12672
> current=60ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12672 current=257
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12673
> current=19ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12673 current=382
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12674
> current=7ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12674 current=48
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12675
> current=54ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12675 current=382
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12676
> current=16ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12676 current=445
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12677
> current=49ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12677 current=508
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12678
> current=90ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12678 current=62
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12679
> current=14ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12679 current=292
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12680
> current=21ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12680 current=193
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12681
> current=88ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12681 current=143
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12682
> current=56ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12682 current=382
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12683
> current=1ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12683 current=33
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12684
> current=18ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12684 current=4
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12685
> current=56ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12685 current=370
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12686
> current=7ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12686 current=48
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12687
> current=7ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12687 current=48
> (XEN) Synced stime skew: max=297847ns avg=451ns samples=12688
> current=44ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12688 current=366
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12689
> current=53ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12689 current=369
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12690
> current=75ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12690 current=382
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12691
> current=31ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12691 current=78
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12692
> current=124ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12692 current=289
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12693
> current=80ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12693 current=330
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12694
> current=22ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12694 current=256
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12695
> current=79ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12695 current=373
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12696
> current=97ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12696 current=382
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12697
> current=119ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12697 current=382
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12698
> current=140ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12698 current=382
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12699
> current=164ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12699 current=334
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12700
> current=160ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12700 current=370
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12701
> current=122ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12701 current=382
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12702
> current=74ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12702 current=175
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12703
> current=65ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12703 current=102
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12704
> current=89ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12704 current=62
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12705
> current=85ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12705 current=116
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12706
> current=5ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12706 current=188
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12707
> current=10ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12707 current=31
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12708
> current=57ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12708 current=65
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12709
> current=54ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12709 current=295
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12710
> current=119ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12710 current=77
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12711
> current=108ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12711 current=47
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12712
> current=78ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12712 current=52
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12713
> current=57ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12713 current=49
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12714
> current=26ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12714 current=42
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12715
> current=56ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12715 current=62
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12716
> current=9ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12716 current=53
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12717
> current=10ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12717 current=52
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12718
> current=1ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12718 current=33
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12719
> current=109ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12719 current=175
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12720
> current=0ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12720 current=36
> (XEN) Synced stime skew: max=297847ns avg=450ns samples=12721
> current=17ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12721 current=256
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12722
> current=85ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12722 current=422
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12723
> current=92ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12723 current=492
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12724
> current=50ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12724 current=387
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12725
> current=94ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12725 current=490
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12726
> current=43ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12726 current=382
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12727
> current=60ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12727 current=57
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12728
> current=48ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12728 current=287
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12729
> current=57ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12729 current=62
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12730
> current=5ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12730 current=251
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12731
> current=90ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12731 current=169
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12732
> current=38ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12732 current=62
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12733
> current=189ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12733 current=345
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12734
> current=6ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12734 current=256
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12735
> current=52ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12735 current=62
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12736
> current=46ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12736 current=294
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12737
> current=90ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12737 current=465
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12738
> current=50ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12738 current=382
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12739
> current=51ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12739 current=382
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12740
> current=53ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12740 current=330
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12741
> current=62ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12741 current=382
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12742
> current=47ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12742 current=62
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12743
> current=4ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12743 current=292
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12744
> current=56ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12744 current=330
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12745
> current=7ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12745 current=48
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12746
> current=87ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12746 current=382
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12747
> current=93ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12747 current=328
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12748
> current=28ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12748 current=98
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12749
> current=29ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12749 current=102
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12750
> current=112ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12750 current=382
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12751
> current=138ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12751 current=372
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12752
> current=108ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12752 current=339
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12753
> current=85ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12753 current=335
> (XEN) Synced stime skew: max=297847ns avg=449ns samples=12754
> current=61ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12754 current=382
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12755
> current=18ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12755 current=256
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12756
> current=3ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12756 current=170
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12757
> current=122ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12757 current=22
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12758
> current=150ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12758 current=285
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12759
> current=269ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12759 current=408
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12760
> current=246ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12760 current=382
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12761
> current=179ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12761 current=52
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12762
> current=165ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12762 current=382
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12763
> current=149ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12763 current=490
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12764
> current=5ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12764 current=256
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12765
> current=60ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12765 current=193
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12766
> current=33ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12766 current=545
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12767
> current=108ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12767 current=256
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12768
> current=25ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12768 current=382
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12769
> current=51ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12769 current=285
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12770
> current=88ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12770 current=103
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12771
> current=56ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12771 current=373
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12772
> current=94ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12772 current=134
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12773
> current=53ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12773 current=382
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12774
> current=5ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12774 current=217
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12775
> current=53ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12775 current=382
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12776
> current=21ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12776 current=297
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12777
> current=11ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12777 current=256
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12778
> current=20ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12778 current=47
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12779
> current=15ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12779 current=48
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12780
> current=9ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12780 current=251
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12781
> current=48ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12781 current=79
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12782
> current=70ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12782 current=382
> (XEN) Synced stime skew: max=297847ns avg=448ns samples=12783
> current=65ns
> (XEN) Synced cycles skew: max=1142 avg=315 samples=12783 current=330
>
> -----Ursprüngliche Nachricht-----
> Von: Carsten Schiers
> Gesendet: Samstag, 28. März 2009 10:53
> An: dan.magenheimer; xen-devel
> Betreff: AW: RE: [Xen-devel] Time went backwards 885 ms
>
> Oh, I didn't know that...
>
> I started to do so. But not all lines will show up in xm
> dmesg. Is there
>
>
>
> any trick to have a bigger buffer to capture it or are only the last
> lines
> of interest?
>
> BR,
> Carsten.
>
> -----Ursprüngliche Nachricht-----
> Von: Dan Magenheimer [mailto:dan.magenheimer@oracle.com]
> Gesendet: Freitag, 27. März 2009 21:20
> An: Carsten Schiers; xen-devel
> Betreff: RE: [Xen-devel] Time went backwards 885 ms
>
> Two possibilities... many power management features
> have gone into Xen and there are many bug fixes post-3.3
> to improve time sync in the presence of power management.
>
> However if power management is NOT happening on your system,
> it's possible that your processors have bad TSC skew
> that Xen's TSC synchronization mechanism is unable to
> handle. (This seems unlikely with a dual core... AMD
> might have information otherwise.)
>
> A nice feature that went into Xen 3.3 is the ability to
> measure the skew between physical processors. The
> "xm debug-key t" takes only one sample, but it can
> be repeated many times and will retain max and avg
> for all of the samples.
>
> Can you do:
>
> # for j in $(seq -w 10000); do xm debug-key t; done
>
> in dom0, then send the output from "xm dmesg | tail"
>
> If you can do this both with Xen 3.3 and 3.4 (when it
> is released, or xen-unstable now), that would be great!
>
> -----Original Message-----
> From: Carsten Schiers [mailto:carsten@schiers.de]
> Sent: Friday, March 27, 2009 3:19 AM
> To: xen-devel
> Subject: [Xen-devel] Time went backwards 885 ms
>
>
> Dear all,
>
> I thought this might be worth again to report:
>
> After rebooting a 3.3.1/2.6.18.8 environment on my AMD 4050e,
> I received
>
>
> a 885ms delta just
> after powernow-k8 loaded:
>
>
> Mar 26 21:28:37 data kernel: powernow-k8: Found 2 AMD Athlon(tm) Dual
> Core Processor 4050e processors (version 2.20.00)
> Mar 26 21:28:37 data kernel: powernow-k8: 0 : fid 0xd
> (2100 MHz), vid
>
>
> 0xe
> Mar 26 21:28:37 data kernel: powernow-k8: 1 : fid 0xc
> (2000 MHz), vid
>
>
> 0xf
> Mar 26 21:28:37 data kernel: powernow-k8: 2 : fid 0xa
> (1800 MHz), vid
>
>
> 0x11
> Mar 26 21:28:37 data kernel: powernow-k8: 3 : fid 0x2
> (1000 MHz), vid
>
>
> 0x16
> Mar 26 21:28:37 data kernel: Timer ISR/1: Time went backwards:
> delta=-885437842 delta_cpu=6562158 shadow=11822142480 off=436198
> processed=12708016520 cpu_p
> rocessed=11816016520
> Mar 26 21:28:37 data kernel: 0: 12704016520
> Mar 26 21:28:37 data kernel: 1: 11816016520
>
>
> Find full xm dmesg, xm info, and syslog of boot attached.
>
> Otherwise, the environment is more stable; Time went backwards appear
> roughly every 2-3 days,
> mostly when there is a 1,0->2,1GHz jump when munin asks for
> CPU. It is
> reduced in addition by a
> 4 sec sampling time of the ondemand govenor.
>
> Will test 3.4 as soon as released.
>
> BR,
> Carsten.
>
>
>
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xensource.com
> http://lists.xensource.com/xen-devel
>
>
>
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xensource.com
> http://lists.xensource.com/xen-devel
>
>
>
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xensource.com
> http://lists.xensource.com/xen-devel
>
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2009-03-28 13:38 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2009-03-27 9:18 Time went backwards 885 ms Carsten Schiers
2009-03-27 20:20 ` Dan Magenheimer
2009-03-28 9:52 ` AW: " Carsten Schiers
2009-03-28 10:22 ` Carsten Schiers
2009-03-28 10:33 ` Carsten Schiers
2009-03-28 13:38 ` Dan Magenheimer
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.