Xen devel - Jul 2012 - Was: Re: [GIT PULL] timer changes for v3.6, Is: Regression introduced by 1e75fa8be9fb61e1af46b5b3b176347a4c958ca1

On Sun, Jul 22, 2012 at 03:34:42PM +0200, Ingo Molnar
wrote:
> Linus,
> 
> Please pull the latest timers-core-for-linus git tree from:
> 
>    git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git
timers-core-for-linus
> 
>    HEAD: eec19d1a0d04c80e66eef634f7b8f460f2ca5643 Merge branch
''linus'' into timers/core
> 
> Continued cleanups of the core time and NTP code, plus more nohz 
> work preparing for tick-less userspace execution.
> 
>  Thanks,
> 
> 	Ingo
> 
> ------------------>
> Frederic Weisbecker (5):
>       nohz: Separate idle sleeping time accounting from nohz logic
>       nohz: Make nohz API agnostic against idle ticks cputime accounting
>       nohz: Rename ts->idle_tick to ts->last_tick
>       nohz: Move ts->idle_calls incrementation into strict idle logic
>       nohz: Move next idle expiry time record into idle logic area
> 
> John Stultz (8):
>       ntp: Fix STA_INS/DEL clearing bug
>       time: Whitespace cleanups per Ingo%27s requests
>       time: Explicitly use u32 instead of int for shift values
>       time: Condense timekeeper.xtime into xtime_sec
I hadn''t looked in details of the patch, but this commit:

commit 1e75fa8be9fb61e1af46b5b3b176347a4c958ca1
Author: John Stultz <john.stultz@linaro.org>
Date:   Fri Jul 13 01:21:53 2012 -0400

    time: Condense timekeeper.xtime into xtime_sec

causes 32-bit (and only 32-bit) bootup time crashes on Xen guests. I
couldn''t
do a git revert on top of Linus''s tree (had a bunch of conflicts), but
with
git bisection it narrowed down to that patch. 

I could also bootup with git commit 55acdddbac1725b80df0c41970505e8a41c84956
(the smp-hotplug-for-linus merge), but with git commit
3992c0321258bdff3666cbaf5225f538ad61a548 (timers-core-for-linus merge aka this
pull)
it went belly up.

This is the guest config:

extra="console=hvc0 debug earlyprintk=xen memblock=debug"
kernel="/mnt/lab/bootstrap-i386/vmlinuz"
ramdisk="/mnt/lab/bootstrap-i386/initramfs.cpio.gz"
mem=10248
vcpus=1
name="bootstrap-i386"
on_crash="preserve"

Attached is the crash log and I am also attaching the .config file and bisect
log.

John, any thoughts? Is Xen clock timer (arch/x86/xen/time.c) code missing
something obvious?

Using config file "/test.xm".
Started domain bootstrap-i386 (id=4)
[    0.000000] console [hvc0] enabled, bootconsole disabled
[    0.000000] Xen: using vcpuop timer interface
[    0.000000] installing Xen timer for CPU 0
[    0.000000] ------------[ cut here ]------------
[    0.000000] WARNING: at /home/konrad/linux/kernel/time/clockevents.c:209
clockevents_program_event+0x176/0x190()
[    0.000000] Modules linked in:
[    0.000000] Pid: 0, comm: swapper/0 Not tainted 3.5.0upstream-00242-g3992c03
#1
[    0.000000] Call Trace:
[    0.000000]  [<c1067aed>] warn_slowpath_common+0x6d/0xa0
[    0.000000]  [<c10aa846>] ? clockevents_program_event+0x176/0x190
[    0.000000]  [<c10aa846>] ? clockevents_program_event+0x176/0x190
[    0.000000]  [<c1067b3d>] warn_slowpath_null+0x1d/0x20
[    0.000000]  [<c10aa846>] clockevents_program_event+0x176/0x190
[    0.000000]  [<c10aaa36>] tick_setup_periodic+0x66/0xa0
[    0.000000]  [<c10aade7>] tick_notify+0x377/0x3d0
[    0.000000]  [<c1511043>] notifier_call_chain+0x43/0x60
[    0.000000]  [<c108985a>] raw_notifier_call_chain+0x1a/0x20
[    0.000000]  [<c10aa1f8>] clockevents_register_device+0x88/0xf0
[    0.000000]  [<c102fb12>] xen_setup_cpu_clockevents+0x22/0x40
[    0.000000]  [<c16bba3a>] xen_time_init+0xb7/0xbf
[    0.000000]  [<c16bcf1c>] x86_late_time_init+0x9/0x10
[    0.000000]  [<c16b7a7f>] start_kernel+0x286/0x317
[    0.000000]  [<c16b766a>] ? kernel_init+0x1cd/0x1cd
[    0.000000]  [<c16b72e6>] i386_start_kernel+0xa9/0xb0
[    0.000000]  [<c16ba609>] xen_start_kernel+0x5c9/0x5d1
[    0.000000] ---[ end trace 4eaa2a86a8e2da22 ]---
[    0.000000] Detected 2899.988 MHz processor.
[1266874889.140126] Calibrating delay loop (skipped), value calculated using
timer frequency.. 5799.97 BogoMIPS (lpj=2899988)
[1266874889.140126] pid_max: default: 32768 minimum: 301
[1266874889.140126] Security Framework initialized
[1266874889.140126] SELinux:  Initializing.
[1266874889.140126] SELinux:  Starting in permissive mode
[1266874889.140126] Mount-cache hash table entries: 512
[1266874889.140126] Initializing cgroup subsys cpuacct
[1266874889.140126] Initializing cgroup subsys freezer
[1266874889.140126] CPU: Physical Processor ID: 0
[1266874889.140126] CPU: Processor Core ID: 1
[1266874889.140126] SMP alternatives: switching to UP code
[1266874889.140126] Freeing SMP alternatives: 24k freed
[1266874889.140126] cpu 0 spinlock event irq 17
[1266874889.140126] Performance Events: 
[1266874889.140126] no APIC, boot with the "lapic" boot parameter to
force-enable it.
[1266874889.140126] no hardware sampling interrupt available.
[1266874889.140126] Broken PMU hardware detected, using software events only.
[1266874889.140126] Failed to access perfctr msr (MSR c0010004 is 3ffb7468b09b)
[1266874889.140126] MCE: In-kernel MCE decoding enabled.
[1266874889.140126] NMI watchdog: disabled (cpu0): hardware events not enabled
[1266874889.140126] Brought up 1 CPUs
[1266874889.140126] kworker/u:0 (12) used greatest stack depth: 7228 bytes left
[1266874889.140126] Grant tables using version 2 layout.
[1266874889.140126] Grant table initialized
[1266874889.140126] RTC time: 165:165:165, date: 165/165/65
[1266874889.140126] NET: Registered protocol family 16
[1266874889.140126] dca service started, version 1.12.1
[1266874889.140126] PCI: setting up Xen PCI frontend stub
[1266874889.140126] PCI: pci_cache_line_size set to 64 bytes
[1266874889.140126] kworker/u:1 (30) used greatest stack depth: 7072 bytes left
[1266874889.140126] bio: create slab <bio-0> at 0
[1266874889.140126] ACPI: Interpreter disabled.
[1266874889.140126] xen/balloon: Initialising balloon driver.
[1266874889.140126] xen-balloon: Initialising balloon driver.
[1266874889.140126] vgaarb: loaded
[1266874889.140126] usbcore: registered new interface driver usbfs
[1266874889.140126] usbcore: registered new interface driver hub
[1266874889.140126] usbcore: registered new device driver usb
[1266874889.140126] PCI: System does not support PCI
[1266874889.140126] PCI: System does not support PCI
[1266874889.140126] NetLabel: Initializing
[1266874889.140126] NetLabel:  domain hash size = 128
[1266874889.140126] NetLabel:  protocols = UNLABELED CIPSOv4
[1266874889.140126] NetLabel:  unlabeled traffic allowed by default
[1266874889.140126] Switching to clocksource xen
[1266874889.140126] pnp: PnP ACPI: disabled
[1266874889.140126] NET: Registered protocol family 2
[1266874889.140126] IP route cache hash table entries: 32768 (order: 5, 131072
bytes)
[1266874889.140126] TCP established hash table entries: 131072 (order: 8,
1048576 bytes)
[1266874889.140126] TCP bind hash table entries: 65536 (order: 7, 524288 bytes)
[1266874889.140126] TCP: Hash tables configured (established 131072 bind 65536)
[1266874889.140126] TCP: reno registered
[1266874889.140126] UDP hash table entries: 512 (order: 2, 16384 bytes)
[1266874889.140126] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[1266874889.140126] NET: Registered protocol family 1
[1266874889.140126] RPC: Registered named UNIX socket transport module.
[1266874889.140126] RPC: Registered udp transport module.
[1266874889.140126] RPC: Registered tcp transport module.
[1266874889.140126] RPC: Registered tcp NFSv4.1 backchannel transport module.
[1266874889.140126] PCI: CLS 0 bytes, default 64
[1266874889.140126] Trying to unpack rootfs image as initramfs...
[1266874889.140126] Freeing initrd memory: 225772k freed
[1266874889.610522] platform rtc_cmos: registered platform RTC device (no PNP
device found)
[1266874889.610522] Machine check injector initialized
[1266874889.610522] microcode: CPU0: patch_level=0x0300000f
[1266874889.610522] microcode: Microcode Update Driver: v2.00
<tigran@aivazian.fsnet.co.uk>, Peter Oruba
[1266874889.610522] audit: initializing netlink socket (disabled)
[1266874889.610522] type=2000 audit(1343044142.474:1): initialized
[1266874889.610522] highmem bounce pool size: 64 pages
[1266874889.610522] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[1266874889.610522] VFS: Disk quotas dquot_6.5.2
[1266874889.610522] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[1266874889.610522] NFS: Registering the id_resolver key type
[1266874889.610522] Key type id_resolver registered
[1266874889.610522] NTFS driver 2.1.30 [Flags: R/W].
[1266874889.610522] msgmni has been set to 1392
[1266874889.610522] SELinux:  Registering netfilter hooks
[1266874889.610522] Block layer SCSI generic (bsg) driver version 0.4 loaded
(major 253)
[1266874889.610522] io scheduler noop registered
[1266874889.610522] io scheduler deadline registered
[1266874889.610522] io scheduler cfq registered (default)
[1266874889.610522] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[1266874889.610522] ioatdma: Intel(R) QuickData Technology Driver 4.00
[1266874889.610522] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[1266874889.610522] Non-volatile memory driver v1.3
[1266874889.610522] Linux agpgart interface v0.103
[1266874889.610522] [drm] Initialized drm 1.1.0 20060810
[1266874889.610522] brd: module loaded
[1266874889.610522] loop: module loaded
[1266874889.610522] Fixed MDIO Bus: probed
[1266874889.610522] tun: Universal TUN/TAP device driver, 1.6
[1266874889.610522] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
[1266874889.610522] ixgbevf: Intel(R) 10 Gigabit PCI Express Virtual Function
Network Driver - version 2.6.0-k
[1266874889.610522] ixgbevf: Copyright (c) 2009 - 2012 Intel Corporation.
[1266874889.610522] ehci_hcd: USB 2.0 ''Enhanced'' Host
Controller (EHCI) Driver
[1266874889.610522] ehci_hcd: block sizes: qh 68 qtd 96 itd 160 sitd 96
[1266874889.610522] ohci_hcd: USB 1.1 ''Open'' Host Controller
(OHCI) Driver
[1266874889.610522] ohci_hcd: block sizes: ed 64 td 64
[1266874889.610522] uhci_hcd: USB Universal Host Controller Interface driver
[1266874889.610522] usbcore: registered new interface driver usblp
[1266874889.610522] usbcore: registered new interface driver libusual
[1266874889.610522] i8042: PNP: No PS/2 controller found. Probing ports
directly.
[1266874889.610522] i8042: No controller found
[1266874889.610522] mousedev: PS/2 mouse device common for all mice
[1266874889.610522] rtc_cmos rtc_cmos: rtc core: registered rtc_cmos as rtc0
[1266874889.610522] rtc_cmos: probe of rtc_cmos failed with error -38
[1266874889.610522] EFI Variables Facility v0.08 2004-May-17
[1266874889.610522] zram: num_devices not specified. Using default: 1
[1266874889.610522] zram: Creating 1 devices ...
[1266874889.610522] Netfilter messages via NETLINK v0.30.
[1266874889.610522] nf_conntrack version 0.5.0 (15942 buckets, 63768 max)
[1266874889.610522] ctnetlink v0.93: registering with nfnetlink.
[1266874889.610522] ip_tables: (C) 2000-2006 Netfilter Core Team
[1266874889.610522] TCP: cubic registered
[1266874889.610522] Initializing XFRM netlink socket
[1266874889.610522] NET: Registered protocol family 10
[1266874889.610522] ip6_tables: (C) 2000-2006 Netfilter Core Team
[1266874889.610522] sit: IPv6 over IPv4 tunneling driver
[1266874889.610522] NET: Registered protocol family 17
[1266874889.610522] Key type dns_resolver registered
[1266874889.610522] Using IPI No-Shortcut mode
[1266874889.610522] PM: Hibernation image not present or could not be loaded.
[1266874889.610522] registered taskstats version 1
[1266874889.610522]   Magic number: 1:252:3141
[1266874889.610522] Freeing unused kernel memory: 512k freed
[1266874889.610522] Write protecting the kernel text: 5204k
[1266874889.610522] Write protecting the kernel read-only data: 1376k
[1266874889.610522] NX-protecting the kernel data: 2988k
[1266874889.610522] divide error: 0000 [#1] SMP 
[1266874889.610522] Modules linked in:
[1266874889.610522] 
[1266874889.610522] Pid: 1, comm: init Tainted: G        W   
3.5.0upstream-00242-g3992c03 #1
[1266874889.610522] EIP: 0061:[<c1245b87>] EFLAGS: 00010046 CPU: 0
[1266874889.610522] EIP is at div64_u64+0x127/0x150
[1266874889.610522] EAX: 00000000 EBX: 00000000 ECX: 00000000 EDX: 00000000
[1266874889.610522] ESI: 00000000 EDI: 00000000 EBP: ebc31eac ESP: ebc31e90
[1266874889.610522]  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0069
[1266874889.610522] CR0: 8005003b CR2: b7626310 CR3: 0eb4c000 CR4: 00000660
[1266874889.610522] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[1266874889.610522] DR6: ffff0ff0 DR7: 00000400
[1266874889.610522] Process init (pid: 1, ti=ebc30000 task=ebc26a10
task.ti=ebc30000)
[1266874889.610522] Stack:
[1266874889.610522]  fa18eedf ffffffff 00000000 00000000 ceb0a840 00000000
00000000 ebc31ef0
[1266874889.610522]  c10945b5 00000000 00000000 00000001 00000000 ceb0a900
00000000 ffffffff
[1266874889.610522]  ffffffff 00000000 00000000 00989680 00000000 ebc26a44
ceb0a840 00000000
[1266874889.610522] Call Trace:
[1266874889.610522]  [<c10945b5>] update_cfs_load+0x125/0x2d0
[1266874889.610522]  [<c10952e4>] enqueue_task_fair+0x54/0x450
[1266874889.610522]  [<c108e460>] enqueue_task+0x60/0x70
[1266874889.610522]  [<c1090eaf>] sched_move_task+0x5f/0x140
[1266874889.610522]  [<c107690e>] ? __lock_task_sighand+0x4e/0xb0
[1266874889.610522]  [<c109a7df>] autogroup_move_group+0x9f/0x100
[1266874889.610522]  [<c109a8e5>] sched_autogroup_create_attach+0x95/0x130
[1266874889.610522]  [<c107a4e9>] sys_setsid+0x79/0xc0
[1266874889.610522]  [<c150dcc9>] syscall_call+0x7/0xb
[1266874889.610522] Code: 24 08 89 54 24 0c 2b 5c 24 08 1b 74 24 0c 39 75 0c 77
a1 eb b7 8d b4 26 00 00 00 00 8b 7d 08 89 d9 31 db 39 d7 77 08 89 d0 31 d2
<f7> f7 89 c3 89 c8 89 5c 24 04 f7 f7 89 04 24 e9 75 ff ff ff 90
[1266874889.610522] EIP: [<c1245b87>] div64_u64+0x127/0x150 SS:ESP
0069:ebc31e90
[1266874889.610522] ---[ end trace 4eaa2a86a8e2da24 ]---
[1266874889.610522] BUG: sleeping function called from invalid context at
/home/konrad/linux/kernel/rwsem.c:20
[1266874889.610522] in_atomic(): 1, irqs_disabled(): 1, pid: 1, name: init
[1266874889.610522] Pid: 1, comm: init Tainted: G      D W   
3.5.0upstream-00242-g3992c03 #1
[1266874889.610522] Call Trace:
[1266874889.610522]  [<c108d7cc>] __might_sleep+0xdc/0x110
[1266874889.610522]  [<c150c067>] down_read+0x17/0x30
[1266874889.610522]  [<c107814a>] exit_signals+0x1a/0x140
[1266874889.610522]  [<c106c0e1>] do_exit+0x91/0x8b0
[1266874889.610522]  [<c150b1d7>] ? printk+0x38/0x3a
[1266874889.610522]  [<c150ead0>] oops_end+0x90/0xd0
[1266874889.610522]  [<c103656f>] die+0x4f/0x70
[1266874889.610522]  [<c150e556>] do_trap+0x96/0xd0
[1266874889.610522]  [<c1034500>] ? do_overflow+0x80/0x80
[1266874889.610522]  [<c1034583>] do_divide_error+0x83/0xa0
[1266874889.610522]  [<c1245b87>] ? div64_u64+0x127/0x150
[1266874889.610522]  [<c108d7de>] ? __might_sleep+0xee/0x110
[1266874889.610522]  [<c10e5e2f>] ? find_get_page+0x2f/0xc0
[1266874889.610522]  [<c105a807>] ? pvclock_clocksource_read+0xf7/0x180
[1266874889.610522]  [<c105a807>] ? pvclock_clocksource_read+0xf7/0x180
[1266874889.610522]  [<c150e30a>] error_code+0x5a/0x60
[1266874889.610522]  [<c1034500>] ? do_overflow+0x80/0x80
[1266874889.610522]  [<c1245b87>] ? div64_u64+0x127/0x150
[1266874889.610522]  [<c10945b5>] update_cfs_load+0x125/0x2d0
[1266874889.610522]  [<c10952e4>] enqueue_task_fair+0x54/0x450
[1266874889.610522]  [<c108e460>] enqueue_task+0x60/0x70
[1266874889.610522]  [<c1090eaf>] sched_move_task+0x5f/0x140
[1266874889.610522]  [<c107690e>] ? __lock_task_sighand+0x4e/0xb0
[1266874889.610522]  [<c109a7df>] autogroup_move_group+0x9f/0x100
[1266874889.610522]  [<c109a8e5>] sched_autogroup_create_attach+0x95/0x130
[1266874889.610522]  [<c107a4e9>] sys_setsid+0x79/0xc0
[1266874889.610522]  [<c150dcc9>] syscall_call+0x7/0xb

On 07/23/2012 07:49 AM, Konrad Rzeszutek Wilk wrote:
> I hadn''t looked in details of the patch, but this commit:
>
> commit 1e75fa8be9fb61e1af46b5b3b176347a4c958ca1
> Author: John Stultz <john.stultz@linaro.org>
> Date:   Fri Jul 13 01:21:53 2012 -0400
>
>      time: Condense timekeeper.xtime into xtime_sec
>
> causes 32-bit (and only 32-bit) bootup time crashes on Xen guests. I
couldn''t
> do a git revert on top of Linus''s tree (had a bunch of conflicts),
but with
> git bisection it narrowed down to that patch.
>
> I could also bootup with git commit
55acdddbac1725b80df0c41970505e8a41c84956
> (the smp-hotplug-for-linus merge), but with git commit
> 3992c0321258bdff3666cbaf5225f538ad61a548 (timers-core-for-linus merge aka
this pull)
> it went belly up.
>
> This is the guest config:
>
> extra="console=hvc0 debug earlyprintk=xen memblock=debug"
> kernel="/mnt/lab/bootstrap-i386/vmlinuz"
> ramdisk="/mnt/lab/bootstrap-i386/initramfs.cpio.gz"
> mem=10248
> vcpus=1
> name="bootstrap-i386"
> on_crash="preserve"
>
> Attached is the crash log and I am also attaching the .config file and
bisect log.
>
> John, any thoughts? Is Xen clock timer (arch/x86/xen/time.c) code missing
something obvious?
Thanks for the testing and the report!  I''ll take a closer look here
and
see.
> Using config file "/test.xm".
> Started domain bootstrap-i386 (id=4)
> [    0.000000] console [hvc0] enabled, bootconsole disabled
> [    0.000000] Xen: using vcpuop timer interface
> [    0.000000] installing Xen timer for CPU 0
> [    0.000000] ------------[ cut here ]------------
> [    0.000000] WARNING: at /home/konrad/linux/kernel/time/clockevents.c:209
clockevents_program_event+0x176/0x190()
> [    0.000000] Modules linked in:
> [    0.000000] Pid: 0, comm: swapper/0 Not tainted
3.5.0upstream-00242-g3992c03 #1
> [    0.000000] Call Trace:
> [    0.000000]  [<c1067aed>] warn_slowpath_common+0x6d/0xa0
> [    0.000000]  [<c10aa846>] ? clockevents_program_event+0x176/0x190
> [    0.000000]  [<c10aa846>] ? clockevents_program_event+0x176/0x190
> [    0.000000]  [<c1067b3d>] warn_slowpath_null+0x1d/0x20
> [    0.000000]  [<c10aa846>] clockevents_program_event+0x176/0x190
> [    0.000000]  [<c10aaa36>] tick_setup_periodic+0x66/0xa0
> [    0.000000]  [<c10aade7>] tick_notify+0x377/0x3d0
> [    0.000000]  [<c1511043>] notifier_call_chain+0x43/0x60
> [    0.000000]  [<c108985a>] raw_notifier_call_chain+0x1a/0x20
> [    0.000000]  [<c10aa1f8>] clockevents_register_device+0x88/0xf0
> [    0.000000]  [<c102fb12>] xen_setup_cpu_clockevents+0x22/0x40
> [    0.000000]  [<c16bba3a>] xen_time_init+0xb7/0xbf
> [    0.000000]  [<c16bcf1c>] x86_late_time_init+0x9/0x10
> [    0.000000]  [<c16b7a7f>] start_kernel+0x286/0x317
> [    0.000000]  [<c16b766a>] ? kernel_init+0x1cd/0x1cd
> [    0.000000]  [<c16b72e6>] i386_start_kernel+0xa9/0xb0
> [    0.000000]  [<c16ba609>] xen_start_kernel+0x5c9/0x5d1
Is this WARN_ON new, as well as the oops?

thanks
-john

On Mon, Jul 23, 2012 at 10:41:49AM -0700, John Stultz
wrote:
> On 07/23/2012 07:49 AM, Konrad Rzeszutek Wilk wrote:
> >I hadn''t looked in details of the patch, but this commit:
> >
> >commit 1e75fa8be9fb61e1af46b5b3b176347a4c958ca1
> >Author: John Stultz <john.stultz@linaro.org>
> >Date:   Fri Jul 13 01:21:53 2012 -0400
> >
> >     time: Condense timekeeper.xtime into xtime_sec
> >
> >causes 32-bit (and only 32-bit) bootup time crashes on Xen guests. I
couldn''t
> >do a git revert on top of Linus''s tree (had a bunch of
conflicts), but with
> >git bisection it narrowed down to that patch.
> >
> >I could also bootup with git commit
55acdddbac1725b80df0c41970505e8a41c84956
> >(the smp-hotplug-for-linus merge), but with git commit
> >3992c0321258bdff3666cbaf5225f538ad61a548 (timers-core-for-linus merge
aka this pull)
> >it went belly up.
> >
> >This is the guest config:
> >
> >extra="console=hvc0 debug earlyprintk=xen memblock=debug"
> >kernel="/mnt/lab/bootstrap-i386/vmlinuz"
> >ramdisk="/mnt/lab/bootstrap-i386/initramfs.cpio.gz"
> >mem=10248
> >vcpus=1
> >name="bootstrap-i386"
> >on_crash="preserve"
> >
> >Attached is the crash log and I am also attaching the .config file and
bisect log.
> >
> >John, any thoughts? Is Xen clock timer (arch/x86/xen/time.c) code
missing something obvious?
> 
> Thanks for the testing and the report!  I''ll take a closer look
here
> and see.
> 
> >Using config file "/test.xm".
> >Started domain bootstrap-i386 (id=4)
> >[    0.000000] console [hvc0] enabled, bootconsole disabled
> >[    0.000000] Xen: using vcpuop timer interface
> >[    0.000000] installing Xen timer for CPU 0
> >[    0.000000] ------------[ cut here ]------------
> >[    0.000000] WARNING: at
/home/konrad/linux/kernel/time/clockevents.c:209
clockevents_program_event+0x176/0x190()
> >[    0.000000] Modules linked in:
> >[    0.000000] Pid: 0, comm: swapper/0 Not tainted
3.5.0upstream-00242-g3992c03 #1
> >[    0.000000] Call Trace:
> >[    0.000000]  [<c1067aed>] warn_slowpath_common+0x6d/0xa0
> >[    0.000000]  [<c10aa846>] ?
clockevents_program_event+0x176/0x190
> >[    0.000000]  [<c10aa846>] ?
clockevents_program_event+0x176/0x190
> >[    0.000000]  [<c1067b3d>] warn_slowpath_null+0x1d/0x20
> >[    0.000000]  [<c10aa846>]
clockevents_program_event+0x176/0x190
> >[    0.000000]  [<c10aaa36>] tick_setup_periodic+0x66/0xa0
> >[    0.000000]  [<c10aade7>] tick_notify+0x377/0x3d0
> >[    0.000000]  [<c1511043>] notifier_call_chain+0x43/0x60
> >[    0.000000]  [<c108985a>] raw_notifier_call_chain+0x1a/0x20
> >[    0.000000]  [<c10aa1f8>]
clockevents_register_device+0x88/0xf0
> >[    0.000000]  [<c102fb12>] xen_setup_cpu_clockevents+0x22/0x40
> >[    0.000000]  [<c16bba3a>] xen_time_init+0xb7/0xbf
> >[    0.000000]  [<c16bcf1c>] x86_late_time_init+0x9/0x10
> >[    0.000000]  [<c16b7a7f>] start_kernel+0x286/0x317
> >[    0.000000]  [<c16b766a>] ? kernel_init+0x1cd/0x1cd
> >[    0.000000]  [<c16b72e6>] i386_start_kernel+0xa9/0xb0
> >[    0.000000]  [<c16ba609>] xen_start_kernel+0x5c9/0x5d1
> 
> Is this WARN_ON new, as well as the oops?
Yes. I don''t see the WARN_ON if I boot the kernel with one git commit
earlier (fee84c43e6afc42295ae8058cbbef9ea5633926c] time: Explicitly use u32
instead of int for shift values).

I do see all the time this WARN_ON and the crash (and also the huge jump in
time reported), when building with git commit
1e75fa8be9fb61e1af46b5b3b176347a4c958ca1] time: Condense timekeeper.xtime into
xtime_sec):

[    0.000000] ---[ end trace 4eaa2a86a8e2da22 ]---
[    0.000000] Detected 2899.988 MHz processor.
[1266874889.140126] Calibrating delay loop (skipped), value calculated using
timer frequency.. 5799.97 BogoMIPS (lpj=2899988)
[1266874889.140126] pid_max: default: 32768 minimum: 301

On 07/23/2012 11:24 AM, Konrad Rzeszutek Wilk wrote:
> On Mon, Jul 23, 2012 at 10:41:49AM -0700, John Stultz wrote:
>> On 07/23/2012 07:49 AM, Konrad Rzeszutek Wilk wrote:
>>> I hadn''t looked in details of the patch, but this commit:
>>>
>>> commit 1e75fa8be9fb61e1af46b5b3b176347a4c958ca1
>>> Author: John Stultz <john.stultz@linaro.org>
>>> Date:   Fri Jul 13 01:21:53 2012 -0400
>>>
>>>      time: Condense timekeeper.xtime into xtime_sec
>>>
>>> causes 32-bit (and only 32-bit) bootup time crashes on Xen guests.
I couldn''t
>>> do a git revert on top of Linus''s tree (had a bunch of
conflicts), but with
>>> git bisection it narrowed down to that patch.
>>>
>>> I could also bootup with git commit
55acdddbac1725b80df0c41970505e8a41c84956
>>> (the smp-hotplug-for-linus merge), but with git commit
>>> 3992c0321258bdff3666cbaf5225f538ad61a548 (timers-core-for-linus
merge aka this pull)
>>> it went belly up.
>>>
>>> This is the guest config:
>>>
>>> extra="console=hvc0 debug earlyprintk=xen memblock=debug"
>>> kernel="/mnt/lab/bootstrap-i386/vmlinuz"
>>> ramdisk="/mnt/lab/bootstrap-i386/initramfs.cpio.gz"
>>> mem=10248
>>> vcpus=1
>>> name="bootstrap-i386"
>>> on_crash="preserve"
>>>
>>> Attached is the crash log and I am also attaching the .config file
and bisect log.
>>>
>>> John, any thoughts? Is Xen clock timer (arch/x86/xen/time.c) code
missing something obvious?
>> Thanks for the testing and the report!  I''ll take a closer
look here
>> and see.
>>
>>> Using config file "/test.xm".
>>> Started domain bootstrap-i386 (id=4)
>>> [    0.000000] console [hvc0] enabled, bootconsole disabled
>>> [    0.000000] Xen: using vcpuop timer interface
>>> [    0.000000] installing Xen timer for CPU 0
>>> [    0.000000] ------------[ cut here ]------------
>>> [    0.000000] WARNING: at
/home/konrad/linux/kernel/time/clockevents.c:209
clockevents_program_event+0x176/0x190()
>>> [    0.000000] Modules linked in:
>>> [    0.000000] Pid: 0, comm: swapper/0 Not tainted
3.5.0upstream-00242-g3992c03 #1
>>> [    0.000000] Call Trace:
>>> [    0.000000]  [<c1067aed>] warn_slowpath_common+0x6d/0xa0
>>> [    0.000000]  [<c10aa846>] ?
clockevents_program_event+0x176/0x190
>>> [    0.000000]  [<c10aa846>] ?
clockevents_program_event+0x176/0x190
>>> [    0.000000]  [<c1067b3d>] warn_slowpath_null+0x1d/0x20
>>> [    0.000000]  [<c10aa846>]
clockevents_program_event+0x176/0x190
>>> [    0.000000]  [<c10aaa36>] tick_setup_periodic+0x66/0xa0
>>> [    0.000000]  [<c10aade7>] tick_notify+0x377/0x3d0
>>> [    0.000000]  [<c1511043>] notifier_call_chain+0x43/0x60
>>> [    0.000000]  [<c108985a>]
raw_notifier_call_chain+0x1a/0x20
>>> [    0.000000]  [<c10aa1f8>]
clockevents_register_device+0x88/0xf0
>>> [    0.000000]  [<c102fb12>]
xen_setup_cpu_clockevents+0x22/0x40
>>> [    0.000000]  [<c16bba3a>] xen_time_init+0xb7/0xbf
>>> [    0.000000]  [<c16bcf1c>] x86_late_time_init+0x9/0x10
>>> [    0.000000]  [<c16b7a7f>] start_kernel+0x286/0x317
>>> [    0.000000]  [<c16b766a>] ? kernel_init+0x1cd/0x1cd
>>> [    0.000000]  [<c16b72e6>] i386_start_kernel+0xa9/0xb0
>>> [    0.000000]  [<c16ba609>] xen_start_kernel+0x5c9/0x5d1
>> Is this WARN_ON new, as well as the oops?
> Yes. I don''t see the WARN_ON if I boot the kernel with one git
commit
> earlier (fee84c43e6afc42295ae8058cbbef9ea5633926c] time: Explicitly use u32
instead of int for shift values).
>
> I do see all the time this WARN_ON and the crash (and also the huge jump in
> time reported), when building with git commit
1e75fa8be9fb61e1af46b5b3b176347a4c958ca1] time: Condense timekeeper.xtime into
xtime_sec):
>
> [    0.000000] ---[ end trace 4eaa2a86a8e2da22 ]---
> [    0.000000] Detected 2899.988 MHz processor.
> [1266874889.140126] Calibrating delay loop (skipped), value calculated
using timer frequency.. 5799.97 BogoMIPS (lpj=2899988)
> [1266874889.140126] pid_max: default: 32768 minimum: 301
Does the following resolve it? If not I have a debug patch I''ll send
you
to try to chase this down.

thanks
-john


diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index f045cc5..cf364db 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -108,13 +108,13 @@ static struct timespec tk_xtime(struct timekeeper *tk)
  static void tk_set_xtime(struct timekeeper *tk, const struct timespec *ts)
  {
  	tk->xtime_sec = ts->tv_sec;
-	tk->xtime_nsec = ts->tv_nsec << tk->shift;
+	tk->xtime_nsec = (u64)ts->tv_nsec << tk->shift;
  }
  
  static void tk_xtime_add(struct timekeeper *tk, const struct timespec *ts)
  {
  	tk->xtime_sec += ts->tv_sec;
-	tk->xtime_nsec += ts->tv_nsec << tk->shift;
+	tk->xtime_nsec += (u64)ts->tv_nsec << tk->shift;
  }
  
  /**

> Does the following resolve it? If not I have a debug patch I''ll
send
> you to try to chase this down.
Yup. That makes it boot without crash and without any WARN_ON.  I am going
to run it overnight on some other machines but so far it looks to have
fixed the regression. So please attach:

Reported-and-Tested-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
> 
> thanks
> -john
> 
> 
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index f045cc5..cf364db 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -108,13 +108,13 @@ static struct timespec tk_xtime(struct timekeeper
*tk)
>  static void tk_set_xtime(struct timekeeper *tk, const struct timespec *ts)
>  {
>  	tk->xtime_sec = ts->tv_sec;
> -	tk->xtime_nsec = ts->tv_nsec << tk->shift;
> +	tk->xtime_nsec = (u64)ts->tv_nsec << tk->shift;
>  }
>  static void tk_xtime_add(struct timekeeper *tk, const struct timespec *ts)
>  {
>  	tk->xtime_sec += ts->tv_sec;
> -	tk->xtime_nsec += ts->tv_nsec << tk->shift;
> +	tk->xtime_nsec += (u64)ts->tv_nsec << tk->shift;
>  }
>  /**
> 
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

On 07/23/2012 12:51 PM, Konrad Rzeszutek Wilk wrote:
>> Does the following resolve it? If not I have a debug patch
I''ll send
>> you to try to chase this down.
> Yup. That makes it boot without crash and without any WARN_ON.  I am going
> to run it overnight on some other machines but so far it looks to have
> fixed the regression. So please attach:
>
> Reported-and-Tested-by: Konrad Rzeszutek Wilk
<konrad.wilk@oracle.com>
Great! Thanks again so much for the testing and quick reporting!
-john

On Mon, Jul 23, 2012 at 1:24 PM, John Stultz <john.stultz@linaro.org>
wrote:
>
> Great! Thanks again so much for the testing and quick reporting!
Hmm. I''m just cutting 3.6-rc1, and noticing that apparently this patch
never reached me. So now -rc1 is broken on 32 bit under Xen.

I''m not going to delay rc1 for this, but I thought I''d point
this out
in the hope that we get it fixed soon. I''ll be around for small fixes
for another day and a half before I''m traveling for vacation.

              Linus

On 08/02/2012 04:52 PM, Linus Torvalds wrote:
> On Mon, Jul 23, 2012 at 1:24 PM, John Stultz <john.stultz@linaro.org>
wrote:
>> Great! Thanks again so much for the testing and quick reporting!
> Hmm. I''m just cutting 3.6-rc1, and noticing that apparently this
patch
> never reached me. So now -rc1 is broken on 32 bit under Xen.
>
> I''m not going to delay rc1 for this, but I thought I''d
point this out
> in the hope that we get it fixed soon. I''ll be around for small
fixes
> for another day and a half before I''m traveling for vacation.
Yea, the fix has been sitting in tip/timers/urgent.  I heard Thomas was 
on vacation, so maybe that''s why he''s not sent the pull
request?

Ingo, could you make the pull request?  Sorry if the commit log didn''t 
make it clear this was more urgent.

thanks
-john

* John Stultz <john.stultz@linaro.org> wrote:
> On 08/02/2012 04:52 PM, Linus Torvalds wrote:
> >On Mon, Jul 23, 2012 at 1:24 PM, John Stultz
<john.stultz@linaro.org> wrote:
> >> Great! Thanks again so much for the testing and quick 
> >> reporting!
> > Hmm. I''m just cutting 3.6-rc1, and noticing that apparently 
> > this patch never reached me. So now -rc1 is broken on 32 bit 
> > under Xen.
> >
> > I''m not going to delay rc1 for this, but I thought
I''d point
> > this out in the hope that we get it fixed soon. I''ll be 
> > around for small fixes for another day and a half before I''m 
> > traveling for vacation.
> 
> Yea, the fix has been sitting in tip/timers/urgent.  I heard 
> Thomas was on vacation, so maybe that''s why he''s not sent
the
> pull request?
> 
> Ingo, could you make the pull request?  Sorry if the commit 
> log didn''t make it clear this was more urgent.
Yeah, it''s pending - I''ve got some other urgent bits pending
as
well, will send the timers/urgent bits with them later today.

Thanks,

	Ingo