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

[Konrad Rzeszutek Wilk <konrad.wilk@xxxxxxxxxx>]

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@xxxxxxxxxx>
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@xxxxxxxxxxxxxxxxxxxx>, 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@xxxxxxxxxxxx>
[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

Attachment: bisect.log
Description: Text document

Attachment: config-time.log
Description: Text document

_______________________________________________
Xen-devel mailing list
Xen-devel@xxxxxxxxxxxxx
http://lists.xen.org/xen-devel