From mboxrd@z Thu Jan 1 00:00:00 1970 From: Konrad Rzeszutek Wilk Subject: Re: 3.4.70+ kernel WARNING spew dysfunction on failed migration Date: Tue, 7 Jan 2014 14:11:56 -0500 Message-ID: <20140107191156.GA10370@phenom.dumpdata.com> References: <21196.19900.136146.867552@mariner.uk.xensource.com> Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Return-path: Content-Disposition: inline In-Reply-To: <21196.19900.136146.867552@mariner.uk.xensource.com> List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Sender: xen-devel-bounces@lists.xen.org Errors-To: xen-devel-bounces@lists.xen.org To: Ian Jackson , boris.ostrovsky@oracle.com, david.vrabel@citrix.com Cc: xen-devel@lists.xen.org List-Id: xen-devel@lists.xenproject.org On Tue, Jan 07, 2014 at 06:55:56PM +0000, Ian Jackson wrote: > I did the following test: > > mv /etc/xen/scripts/block /etc/xen/scripts/block.aside > xl migrate debian.guest.osstest localhost > > xl did what appears to be the right thing: it did most of the > migration, failed to run the block scripts at the end of the > migration, and destroyed the destination domain and instead resumed > the source guest. > > However, the source guest immediately went mad spewing WARNINGs and > was after that no longer contactable via the network and not > apparently responsive on the console. See below. > > This is with: > > [ 0.000000] Linux version 3.4.70+ (osstest@rice-weevil) (gcc > version 4.4.5 (Debian 4.4.5-8) ) #1 SMP Wed Dec 4 03:14:51 GMT 2013 > > For reasons I don't understand it doesn't seem to print the actual > kernel git hash in dmesg, but I think it was that from flight 22264, > i.e. 234d96ee0f3b8e49501d068a2a3165aa4db60903. It's i386, on a > 64-bit Xen. This a bit of ancient kernel. Does it show up with 3.12? CC-ing the other maintainers. > > Thanks, > Ian. > > debian login: [ 124.595658] PM: freeze of devices complete after 2.980 msecs > [ 124.595991] PM: late freeze of devices complete after 0.013 msecs > [ 124.600919] PM: noirq freeze of devices complete after 4.884 msecs > [ 124.601105] Grant tables using version 2 layout. > [ 124.601105] ------------[ cut here ]------------ > [ 124.601105] kernel BUG at drivers/xen/events.c:1582! > [ 124.601105] invalid opcode: 0000 [#1] SMP > [ 124.601105] Modules linked in: [last unloaded: scsi_wait_scan] > [ 124.601105] > [ 124.601105] Pid: 6, comm: migration/0 Not tainted 3.4.70+ #1 > [ 124.601105] EIP: 0061:[] EFLAGS: 00010082 CPU: 0 > [ 124.601105] EIP is at xen_irq_resume+0x215/0x370 > [ 124.601105] EAX: ffffffef EBX: deadbeef ECX: deadbeef EDX: 00000000 > [ 124.601105] ESI: c190b020 EDI: df461f24 EBP: df451eb8 ESP: df451e10 > [ 124.601105] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0069 > [ 124.601105] CR0: 8005003b CR2: 08b7c8a8 CR3: 038f0000 CR4: 00002660 > [ 124.601105] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000 > [ 124.601105] DR6: ffff0ff0 DR7: 00000400 > [ 124.601105] Process migration/0 (pid: 6, ti=df450000 task=df43d860 task.ti=df450000) > [ 124.601105] Stack: > [ 124.601105] c104ea40 df451e18 c398b80c deadbeef df461f10 df451e58 c12f350a c19b165c > [ 124.601105] df451e94 00000003 df451e78 c190b080 c190b020 00000000 00000010 00000000 > [ 124.601105] 00000000 00000000 9420f17e 0008a6c2 fc798ba3 0008a6df 00000004 00000413 > [ 124.601105] Call Trace: > [ 124.601105] [] ? xen_iret_crit_fixup+0x3c/0x3c > [ 124.601105] [] ? gnttab_map_frames_v2+0xda/0x120 > [ 124.601105] [] ? xen_spin_lock+0xa0/0x100 > [ 124.601105] [] ? xen_mm_unpin_all+0x65/0x80 > [ 124.601105] [] xen_suspend+0x8d/0xc0 > [ 124.601105] [] stop_machine_cpu_stop+0x9b/0x110 > [ 124.601105] [] cpu_stopper_thread+0xc7/0x1a0 > [ 124.601105] [] ? finish_task_switch+0x5f/0xe0 > [ 124.601105] [] ? stop_one_cpu_nowait+0x40/0x40 > [ 124.601105] [] ? default_wake_function+0xb/0x10 > [ 124.601105] [] ? __wake_up_common+0x40/0x70 > [ 124.601105] [] ? _raw_spin_unlock_irqrestore+0x2d/0x50 > [ 124.601105] [] ? complete+0x49/0x60 > [ 124.601105] [] ? res_counter_charge+0x180/0x180 > [ 124.601105] [] kthread+0x74/0x80 > [ 124.601105] [] ? kthread_freezable_should_stop+0x60/0x60 > [ 124.601105] [] kernel_thread_helper+0x6/0x10 > [ 124.601105] Code: 22 e8 ff ff 8b 55 8c 89 d8 e8 88 e6 ff ff 83 45 94 01 83 7d 94 04 0f 84 80 fe ff ff 8b 55 8c 8b 04 95 e0 11 88 c1 e9 64 ff ff ff <0f> 0b eb fe 0f 0b eb fe 8b 1d 00 60 85 c1 81 fb 00 60 85 c1 74 > [ 124.601105] EIP: [] xen_irq_resume+0x215/0x370 SS:ESP 0069:df451e10 > [ 124.601105] ---[ end trace 69a5c8cd56e77bce ]--- > [ 124.601105] ------------[ cut here ]------------ > [ 124.601105] WARNING: at kernel/time/tick-sched.c:464 tick_nohz_idle_enter+0x7a/0x90() > [ 124.601105] Modules linked in: [last unloaded: scsi_wait_scan] > [ 124.601105] Pid: 0, comm: swapper/0 Tainted: G D 3.4.70+ #1 > [ 124.601105] Call Trace: > [ 124.601105] [] warn_slowpath_common+0x6d/0xa0 > [ 124.601105] [] ? tick_nohz_idle_enter+0x7a/0x90 > [ 124.601105] [] ? tick_nohz_idle_enter+0x7a/0x90 > [ 124.601105] [] warn_slowpath_null+0x1d/0x20 > [ 124.601105] [] tick_nohz_idle_enter+0x7a/0x90 > [ 124.601105] [] cpu_idle+0x1a/0xa0 > [ 124.601105] [] rest_init+0x58/0x60 > [ 124.601105] [] start_kernel+0x355/0x35b > [ 124.601105] [] ? kernel_init+0x1cf/0x1cf > [ 124.601105] [] i386_start_kernel+0xa9/0xb0 > [ 124.601105] [] xen_start_kernel+0x5c4/0x5cc > [ 124.601105] ---[ end trace 69a5c8cd56e77bcf ]--- > [ 124.601105] ------------[ cut here ]------------ > [ 124.601105] WARNING: at kernel/time/timekeeping.c:266 ktime_get+0xe9/0x100() > [ 124.601105] Modules linked in: [last unloaded: scsi_wait_scan] > [ 124.601105] Pid: 0, comm: swapper/0 Tainted: G D W 3.4.70+ #1 > [ 124.601105] Call Trace: > [ 124.601105] [] warn_slowpath_common+0x6d/0xa0 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] warn_slowpath_null+0x1d/0x20 > [ 124.601105] [] ktime_get+0xe9/0x100 > [ 124.601105] [] tick_nohz_stop_sched_tick+0x34/0x3f0 > [ 124.601105] [] ? print_oops_end_marker+0x2a/0x30 > [ 124.601105] [] ? warn_slowpath_common+0x7d/0xa0 > [ 124.601105] [] ? tick_nohz_idle_enter+0x7a/0x90 > [ 124.601105] [] tick_nohz_idle_enter+0x45/0x90 > [ 124.601105] [] cpu_idle+0x1a/0xa0 > [ 124.601105] [] rest_init+0x58/0x60 > [ 124.601105] [] start_kernel+0x355/0x35b > [ 124.601105] [] ? kernel_init+0x1cf/0x1cf > [ 124.601105] [] i386_start_kernel+0xa9/0xb0 > [ 124.601105] [] xen_start_kernel+0x5c4/0x5cc > [ 124.601105] ---[ end trace 69a5c8cd56e77bd0 ]--- > [ 124.601105] ------------[ cut here ]------------ > [ 124.601105] WARNING: at kernel/time/timekeeping.c:266 ktime_get+0xe9/0x100() > [ 124.601105] Modules linked in: [last unloaded: scsi_wait_scan] > [ 124.601105] Pid: 0, comm: swapper/0 Tainted: G D W 3.4.70+ #1 > [ 124.601105] Call Trace: > [ 124.601105] [] warn_slowpath_common+0x6d/0xa0 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] warn_slowpath_null+0x1d/0x20 > [ 124.601105] [] ktime_get+0xe9/0x100 > [ 124.601105] [] tick_check_idle+0x39/0xf0 > [ 124.601105] [] irq_enter+0x4c/0x70 > [ 124.601105] [] xen_evtchn_do_upcall+0x16/0x30 > [ 124.601105] [] xen_do_upcall+0x7/0xc > [ 124.601105] [] ? hypercall_page+0x227/0x1000 > [ 124.601105] [] ? xen_force_evtchn_callback+0x1a/0x30 > [ 124.601105] [] check_events+0x8/0xc > [ 124.601105] [] ? xen_clocksource_get_cycles+0xc/0xc > [ 124.601105] [] ? xen_irq_enable_direct_reloc+0x4/0x4 > [ 124.601105] [] ? tick_nohz_idle_enter+0x54/0x90 > [ 124.601105] [] cpu_idle+0x1a/0xa0 > [ 124.601105] [] rest_init+0x58/0x60 > [ 124.601105] [] start_kernel+0x355/0x35b > [ 124.601105] [] ? kernel_init+0x1cf/0x1cf > [ 124.601105] [] i386_start_kernel+0xa9/0xb0 > [ 124.601105] [] xen_start_kernel+0x5c4/0x5cc > [ 124.601105] ---[ end trace 69a5c8cd56e77bd1 ]--- > [ 124.601105] ------------[ cut here ]------------ > [ 124.601105] WARNING: at kernel/time/timekeeping.c:266 ktime_get+0xe9/0x100() > [ 124.601105] Modules linked in: [last unloaded: scsi_wait_scan] > [ 124.601105] Pid: 0, comm: swapper/0 Tainted: G D W 3.4.70+ #1 > [ 124.601105] Call Trace: > [ 124.601105] [] warn_slowpath_common+0x6d/0xa0 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] warn_slowpath_null+0x1d/0x20 > [ 124.601105] [] ktime_get+0xe9/0x100 > [ 124.601105] [] tick_nohz_stop_sched_tick+0x34/0x3f0 > [ 124.601105] [] ? info_for_irq+0x8/0x20 > [ 124.601105] [] ? evtchn_from_irq+0x13/0x40 > [ 124.601105] [] ? xen_clocksource_read+0x19/0x20 > [ 124.601105] [] ? __xen_evtchn_do_upcall+0x258/0x2b0 > [ 124.601105] [] tick_nohz_irq_exit+0x3f/0x80 > [ 124.601105] [] irq_exit+0x4f/0xb0 > [ 124.601105] [] xen_evtchn_do_upcall+0x20/0x30 > [ 124.601105] [] xen_do_upcall+0x7/0xc > [ 124.601105] [] ? hypercall_page+0x227/0x1000 > [ 124.601105] [] ? xen_force_evtchn_callback+0x1a/0x30 > [ 124.601105] [] check_events+0x8/0xc > [ 124.601105] [] ? xen_clocksource_get_cycles+0xc/0xc > [ 124.601105] [] ? xen_irq_enable_direct_reloc+0x4/0x4 > [ 124.601105] [] ? tick_nohz_idle_enter+0x54/0x90 > [ 124.601105] [] cpu_idle+0x1a/0xa0 > [ 124.601105] [] rest_init+0x58/0x60 > [ 124.601105] [] start_kernel+0x355/0x35b > [ 124.601105] [] ? kernel_init+0x1cf/0x1cf > [ 124.601105] [] i386_start_kernel+0xa9/0xb0 > [ 124.601105] [] xen_start_kernel+0x5c4/0x5cc > [ 124.601105] ---[ end trace 69a5c8cd56e77bd2 ]--- > [ 124.601105] ------------[ cut here ]------------ > [ 124.601105] WARNING: at kernel/time/timekeeping.c:266 ktime_get+0xe9/0x100() > [ 124.601105] Modules linked in: [last unloaded: scsi_wait_scan] > [ 124.601105] Pid: 0, comm: swapper/0 Tainted: G D W 3.4.70+ #1 > [ 124.601105] Call Trace: > [ 124.601105] [] warn_slowpath_common+0x6d/0xa0 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] warn_slowpath_null+0x1d/0x20 > [ 124.601105] [] ktime_get+0xe9/0x100 > [ 124.601105] [] tick_check_idle+0x39/0xf0 > [ 124.601105] [] irq_enter+0x4c/0x70 > [ 124.601105] [] xen_evtchn_do_upcall+0x16/0x30 > [ 124.601105] [] xen_do_upcall+0x7/0xc > [ 124.601105] [] ? hypercall_page+0x3a7/0x1000 > [ 124.601105] [] ? xen_safe_halt+0x12/0x20 > [ 124.601105] [] ? xen_irq_disable+0x10/0x10 > [ 124.601105] [] default_idle+0x5b/0x190 > [ 124.601105] [] ? svm_set_tsc_khz+0x74/0x140 > [ 124.601105] [] cpu_idle+0x6f/0xa0 > [ 124.601105] [] rest_init+0x58/0x60 > [ 124.601105] [] start_kernel+0x355/0x35b > [ 124.601105] [] ? kernel_init+0x1cf/0x1cf > [ 124.601105] [] i386_start_kernel+0xa9/0xb0 > [ 124.601105] [] xen_start_kernel+0x5c4/0x5cc > [ 124.601105] ---[ end trace 69a5c8cd56e77bd3 ]--- > [ 124.601105] ------------[ cut here ]------------ > [ 124.601105] WARNING: at kernel/time/timekeeping.c:266 ktime_get+0xe9/0x100() > [ 124.601105] Modules linked in: [last unloaded: scsi_wait_scan] > [ 124.601105] Pid: 0, comm: swapper/0 Tainted: G D W 3.4.70+ #1 > [ 124.601105] Call Trace: > [ 124.601105] [] warn_slowpath_common+0x6d/0xa0 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] warn_slowpath_null+0x1d/0x20 > [ 124.601105] [] ktime_get+0xe9/0x100 > [ 124.601105] [] tick_nohz_stop_sched_tick+0x34/0x3f0 > [ 124.601105] [] ? info_for_irq+0x8/0x20 > [ 124.601105] [] ? evtchn_from_irq+0x13/0x40 > [ 124.601105] [] ? xen_clocksource_read+0x19/0x20 > [ 124.601105] [] ? __xen_evtchn_do_upcall+0x258/0x2b0 > [ 124.601105] [] tick_nohz_irq_exit+0x3f/0x80 > [ 124.601105] [] irq_exit+0x4f/0xb0 > [ 124.601105] [] xen_evtchn_do_upcall+0x20/0x30 > [ 124.601105] [] xen_do_upcall+0x7/0xc > [ 124.601105] [] ? hypercall_page+0x3a7/0x1000 > [ 124.601105] [] ? xen_safe_halt+0x12/0x20 > [ 124.601105] [] ? xen_irq_disable+0x10/0x10 > [ 124.601105] [] default_idle+0x5b/0x190 > [ 124.601105] [] ? svm_set_tsc_khz+0x74/0x140 > [ 124.601105] [] cpu_idle+0x6f/0xa0 > [ 124.601105] [] rest_init+0x58/0x60 > [ 124.601105] [] start_kernel+0x355/0x35b > [ 124.601105] [] ? kernel_init+0x1cf/0x1cf > [ 124.601105] [] i386_start_kernel+0xa9/0xb0 > [ 124.601105] [] xen_start_kernel+0x5c4/0x5cc > [ 124.601105] ---[ end trace 69a5c8cd56e77bd4 ]--- > [ 124.601105] ------------[ cut here ]------------ > [ 124.601105] WARNING: at kernel/time/timekeeping.c:266 ktime_get+0xe9/0x100() > [ 124.601105] Modules linked in: [last unloaded: scsi_wait_scan] > [ 124.601105] Pid: 0, comm: swapper/0 Tainted: G D W 3.4.70+ #1 > [ 124.601105] Call Trace: > [ 124.601105] [] warn_slowpath_common+0x6d/0xa0 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] ? ktime_get+0xe9/0x100 > [ 124.601105] [] warn_slowpath_null+0x1d/0x20 > [ 124.601105] [] ktime_get+0xe9/0x100 > [ 124.601105] [] tick_check_idle+0x39/0xf0 > [ 124.601105] [] irq_enter+0x4c/0x70 > [ 124.601105] [] xen_evtchn_do_upcall+0x16/0x30 > [ 124.601105] [] xen_do_upcall+0x7/0xc > [ 124.601105] [] ? hypercall_page+0x3a7/0x1000 > [ 124.601105] [] ? xen_safe_halt+0x12/0x20 > [ 124.601105] [] ? xen_irq_disable+0x10/0x10 > [ 124.601105] [] default_idle+0x5b/0x190 > [ 124.601105] [] ? svm_set_tsc_khz+0x74/0x140 > [ 124.601105] [] cpu_idle+0x6f/0xa0 > [ 124.601105] [] rest_init+0x58/0x60 > [ 124.601105] [] start_kernel+0x355/0x35b > [ 124.601105] [] ? kernel_init+0x1cf/0x1cf > [ 124.601105] [] i386_start_kernel+0xa9/0xb0 > [ 124.601105] [] xen_start_kernel+0x5c4/0x5cc > [ 124.601105] ---[ end trace 69a5c8cd56e77bd5 ]--- > [ 124.601105] ------------[ cut here ]------------