On 2017-10-05 06:20 AM, Konrad Rzeszutek Wilk wrote:
On Wed, Oct 04, 2017 at 08:26:27PM +0200, Philipp Hahn wrote:
Hello,
Adding Ankur to this as I think he saw something similar.
But in the meantime - do you see this with the latest version of Linux?
with linux-4.9.52 running on Debian-Wheezy with Xen-4.1 I observed
several stuck processes: Here is one (truncated) dump of the Linux
kernel messages:
[<ffffffff8160db6d>] ? __schedule+0x23d/0x6d0
[<ffffffff8160e8a0>] ? bit_wait_timeout+0x90/0x90
[<ffffffff8160e032>] ? schedule+0x32/0x80
[<ffffffff8161150c>] ? schedule_timeout+0x1ec/0x360
[<ffffffff8130f277>] ? __blk_mq_run_hw_queue+0x327/0x3e0* see below
[<ffffffff8101b7f1>] ? xen_clocksource_get_cycles+0x11/0x20
[<ffffffff8160e8a0>] ? bit_wait_timeout+0x90/0x90
[<ffffffff8160d8b4>] ? io_schedule_timeout+0xb4/0x130
[<ffffffff810bb6f7>] ? prepare_to_wait+0x57/0x80
[<ffffffff8160e8b7>] ? bit_wait_io+0x17/0x60
[<ffffffff8160e3ac>] ? __wait_on_bit+0x5c/0x90
[<ffffffff8160e8a0>] ? bit_wait_timeout+0x90/0x90
[<ffffffff8160e50e>] ? out_of_line_wait_on_bit+0x7e/0xa0
[<ffffffff810bba20>] ? autoremove_wake_function+0x40/0x40
[<ffffffffc00abd18>] ? jbd2_journal_commit_transaction+0xd48/0x17e0 [jbd2]
[<ffffffff810247d9>] ? __switch_to+0x2c9/0x720
[<ffffffff810e67fd>] ? try_to_del_timer_sync+0x4d/0x80
[<ffffffffc00b099d>] ? kjournald2+0xdd/0x280 [jbd2]
[<ffffffff810bb9e0>] ? wake_up_atomic_t+0x30/0x30
[<ffffffffc00b08c0>] ? commit_timeout+0x10/0x10 [jbd2]
[<ffffffff81097660>] ? kthread+0xf0/0x110
[<ffffffff810247d9>] ? __switch_to+0x2c9/0x720
[<ffffffff81097570>] ? kthread_park+0x60/0x60
[<ffffffff81612bb5>] ? ret_from_fork+0x25/0x30
This looks like this race: https://patchwork.kernel.org/patch/9853443/
Can you dump the output of: cat /sys/block/$xen-frontend-device/mq/*/tags
If you've hit this bug, one or more of the MQs would be wedged and
the nr_free in one or more of the queues would be 0 and will not
change.
Ankur
NMI backtrace for cpu 2
CPU: 2 PID: 35 Comm: khungtaskd Not tainted 4.9.0-ucs105-amd64 #1 Debian
4.9.30-2A~4.2.0.201709271649
0000000000000000 ffffffff81331935 0000000000000000 0000000000000002
ffffffff81335e60 0000000000000002 ffffffff8104cb70 ffff8801f0c90e80
ffffffff81335f6a ffff8801f0c90e80 00000000003fffbc ffffffff81128048
Call Trace:
[<ffffffff81331935>] ? dump_stack+0x5c/0x77
[<ffffffff81335e60>] ? nmi_cpu_backtrace+0x90/0xa0
[<ffffffff8104cb70>] ? irq_force_complete_move+0x140/0x140
[<ffffffff81335f6a>] ? nmi_trigger_cpumask_backtrace+0xfa/0x130
[<ffffffff81128048>] ? watchdog+0x2b8/0x330
[<ffffffff81127d90>] ? reset_hung_task_detector+0x10/0x10
[<ffffffff81097660>] ? kthread+0xf0/0x110
[<ffffffff810247d9>] ? __switch_to+0x2c9/0x720
[<ffffffff81097570>] ? kthread_park+0x60/0x60
[<ffffffff81612bb5>] ? ret_from_fork+0x25/0x30
Sending NMI from CPU 2 to CPUs 0-1,3:
NMI backtrace for cpu 1
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.9.0-ucs105-amd64 #1 Debian
4.9.30-2A~4.2.0.201709271649
task: ffff8801f4a02ec0 task.stack: ffffc90040ca4000
RIP: e030:[<ffffffff810013aa>] [<ffffffff810013aa>]
xen_hypercall_sched_op+0xa/0x20
RSP: e02b:ffffc90040ca7ed0 EFLAGS: 00000246
RAX: 0000000000000000 RBX: ffff8801f4a02ec0 RCX: ffffffff810013aa
RDX: ffffffff81c4ba70 RSI: 0000000000000000 RDI: 0000000000000001
RBP: 0000000000000001 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000007ff0 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000000 R14: ffff8801f4a02ec0 R15: ffff8801f4a02ec0
FS: 00007f23ac595700(0000) GS:ffff8801f5a80000(0000) knlGS:0000000000000000
CS: e033 DS: 002b ES: 002b CR0: 0000000080050033
CR2: 00007f52537d6d46 CR3: 00000001bba23000 CR4: 0000000000002660
Stack:
ffff8801bb832201 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffff8801f4a02ec0 0000000000000001 ffffffff810bc280 ffff8801f4a02ec0
ffff8801f4a02ec0 c0a995961d41240f addce6dcadd009c9 0000000000000000
Call Trace:
[<ffffffff8101b55c>] ? xen_safe_halt+0xc/0x20
[<ffffffff81611ec8>] ? default_idle+0x18/0xd0
[<ffffffff810bc280>] ? cpu_startup_entry+0x1f0/0x260
Code: cc 51 41 53 b8 1c 00 00 00 0f 05 41 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc
cc cc cc cc cc cc cc 51 41 53 b8 1d 00 00 00 0f 05 <41> 5b 59 c3 cc cc cc cc cc
cc cc cc cc cc cc cc cc cc cc cc cc
NMI backtrace for cpu 3
CPU: 3 PID: 0 Comm: swapper/3 Not tainted 4.9.0-ucs105-amd64 #1 Debian
4.9.30-2A~4.2.0.201709271649
task: ffff8801f4a24f00 task.stack: ffffc90040cb4000
RIP: e030:[<ffffffff810013aa>] [<ffffffff810013aa>]
xen_hypercall_sched_op+0xa/0x20
RSP: e02b:ffffc90040cb7ed0 EFLAGS: 00000246
RAX: 0000000000000000 RBX: ffff8801f4a24f00 RCX: ffffffff810013aa
RDX: ffffffff81c4ba70 RSI: 0000000000000000 RDI: 0000000000000001
RBP: 0000000000000003 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000007ff0 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000000 R14: ffff8801f4a24f00 R15: ffff8801f4a24f00
FS: 00007f1a2af19700(0000) GS:ffff8801f5b80000(0000) knlGS:0000000000000000
CS: e033 DS: 002b ES: 002b CR0: 0000000080050033
CR2: 00007f4a5416b000 CR3: 00000001d83ec000 CR4: 0000000000002660
Stack:
0000000000000001 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffff8801f4a24f00 0000000000000003 ffffffff810bc280 ffff8801f4a24f00
ffff8801f4a24f00 77816deb133b9979 addce6dcadd009c9 0000000000000000
Call Trace:
[<ffffffff8101b55c>] ? xen_safe_halt+0xc/0x20
[<ffffffff81611ec8>] ? default_idle+0x18/0xd0
[<ffffffff810bc280>] ? cpu_startup_entry+0x1f0/0x260
Code: cc 51 41 53 b8 1c 00 00 00 0f 05 41 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc
cc cc cc cc cc cc cc 51 41 53 b8 1d 00 00 00 0f 05 <41> 5b 59 c3 cc cc cc cc cc
cc cc cc cc cc cc cc cc cc cc cc cc
NMI backtrace for cpu 0
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.9.0-ucs105-amd64 #1 Debian
4.9.30-2A~4.2.0.201709271649
task: ffffffff81c0e540 task.stack: ffffffff81c00000
RIP: e030:[<ffffffff810013aa>] [<ffffffff810013aa>]
xen_hypercall_sched_op+0xa/0x20
RSP: e02b:ffffffff81c03e90 EFLAGS: 00000246
RAX: 0000000000000000 RBX: ffffffff81c0e540 RCX: ffffffff810013aa
RDX: ffffffff81c4ba70 RSI: 0000000000000000 RDI: 0000000000000001
RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000007ff0 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000000 R14: ffffffff81c0e540 R15: ffffffff81c0e540
FS: 00007f977d3c2700(0000) GS:ffff8801f5a00000(0000) knlGS:0000000000000000
CS: e033 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 000055ae9becabc8 CR3: 00000001d6a40000 CR4: 0000000000002660
Stack:
0000000000000001 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffffffff81c0e540 0000000000000000 ffffffff810bc280 ffffffff81c0e540
ffffffff81c0e540 ebeac214e330bd3f addce6dcadd009c9 ffffffffffffffff
Call Trace:
[<ffffffff8101b55c>] ? xen_safe_halt+0xc/0x20
[<ffffffff81611ec8>] ? default_idle+0x18/0xd0
[<ffffffff810bc280>] ? cpu_startup_entry+0x1f0/0x260
[<ffffffff81d4bf84>] ? start_kernel+0x46d/0x48d
[<ffffffff81d510e6>] ? xen_start_kernel+0x52e/0x538
Code: cc 51 41 53 b8 1c 00 00 00 0f 05 41 5b 59 c3 cc cc cc cc cc cc cc cc cc cc cc
cc cc cc cc cc cc cc 51 41 53 b8 1d 00 00 00 0f 05 <41> 5b 59 c3 cc cc cc cc cc
cc cc cc cc cc cc cc cc cc cc cc cc
Looking at the dis-assembly of xen_clocksource_get_cycles() in
arch/x86/xen/time.c I see no path how that should call
__blk_mq_run_hw_queue():
00000000000001a0 <xen_clocksource_get_cycles> mov %gs:0x0(%rip),%rdi #
00000000000001a8 <xen_clocksource_get_cycles+0x8>
00000000000001a8 <xen_clocksource_get_cycles+0x8> add $0x20,%rdi
ret = pvclock_clocksource_read(src);
00000000000001ac <xen_clocksource_get_cycles+0xc> callq 00000000000001b1
<xen_clocksource_get_cycles+0x11>
}
static cycle_t xen_clocksource_get_cycles(struct clocksource *cs)
{
return xen_clocksource_read();
}
00000000000001b1 <xen_clocksource_get_cycles+0x11> retq
00000000000001b2 <xen_clocksource_get_cycles+0x12> data16 data16 data16 data16
nopw %cs:0x0(%rax,%rax,1)
static void xen_read_wallclock(struct timespec *ts)
{
struct shared_info *s = HYPERVISOR_shared_info;
struct pvclock_wall_clock *wall_clock = &(s->wc);
00000000000001c0 <xen_get_wallclock> mov 0x0(%rip),%rax # 00000000000001c7
<xen_get_wallclock+0x7>
Here's another dump, which diverges from xen_clocksource_get_cycles() to
some completely other function:
INFO: task btrfs-transacti:522 blocked for more than 300 seconds.
btrfs-transacti D 0 522 2 0x00000000
ffff8801f3836000 0000000000000000 ffff8801f4a24f00 ffff8801f32da1c0
ffff8801f5b18780 ffffc9004199fa40 ffffffff8160cd2d 0000000000000000
ffff8801741a58a8 0000000000000102 000000000000000e ffff8801f32da1c0
Call Trace:
[<ffffffff8160cd2d>] ? __schedule+0x23d/0x6d0
[<ffffffff8160da60>] ? bit_wait_timeout+0x90/0x90
[<ffffffff8160d1f2>] ? schedule+0x32/0x80
[<ffffffff81610729>] ? schedule_timeout+0x249/0x300
***
[<ffffffff8101b7d1>] ? xen_clocksource_get_cycles+0x11/0x20
[<ffffffff8160da60>] ? bit_wait_timeout+0x90/0x90
[<ffffffff8160ca74>] ? io_schedule_timeout+0xb4/0x130
[<ffffffff810bb5e7>] ? prepare_to_wait+0x57/0x80
[<ffffffff8160da77>] ? bit_wait_io+0x17/0x60
[<ffffffff8160d56c>] ? __wait_on_bit+0x5c/0x90
[<ffffffff8117e18e>] ? find_get_pages_tag+0x15e/0x300
[<ffffffff8117d016>] ? wait_on_page_bit+0x86/0xa0
[<ffffffff810bb910>] ? autoremove_wake_function+0x40/0x40
[<ffffffff8117d107>] ? __filemap_fdatawait_range+0xd7/0x150
[<ffffffff8117d18f>] ? filemap_fdatawait_range+0xf/0x30
[<ffffffffc0175643>] ? btrfs_wait_ordered_range+0x73/0x110 [btrfs]
[<ffffffffc01a2a0d>] ? btrfs_wait_cache_io+0x5d/0x1f0 [btrfs]
[<ffffffffc0141a36>] ? btrfs_write_dirty_block_groups+0x106/0x380 [btrfs]
[<ffffffffc0140c5d>] ? btrfs_run_delayed_refs+0x1fd/0x2b0 [btrfs]
[<ffffffffc01551d7>] ? commit_cowonly_roots+0x257/0x2f0 [btrfs]
[<ffffffffc0157a24>] ? btrfs_commit_transaction+0x4e4/0xa40 [btrfs]
[<ffffffffc015801d>] ? start_transaction+0x9d/0x4a0 [btrfs]
[<ffffffffc01523a2>] ? transaction_kthread+0x1b2/0x1f0 [btrfs]
[<ffffffffc01521f0>] ? btrfs_cleanup_transaction+0x580/0x580 [btrfs]
[<ffffffff810975c0>] ? kthread+0xf0/0x110
[<ffffffff8102476b>] ? __switch_to+0x2bb/0x700
[<ffffffff810974d0>] ? kthread_park+0x60/0x60
[<ffffffff81611d35>] ? ret_from_fork+0x25/0x30
And another one:
INFO: task smbd:20101 blocked for more than 300 seconds.
smbd D 0 20101 1714 0x00000000
ffff8801f01cac00 0000000000000000 ffff8801f4a241c0 ffff88007f9a5240
ffff8801f5b98780 ffffc90049a33bc0 ffffffff8160cd2d ffff8800f78bb5b0
fd2236313fb5274b 000000008dc3c1a0 ffff8801f3ef0a40 ffff88007f9a5240
Call Trace:
[<ffffffff8160cd2d>] ? __schedule+0x23d/0x6d0
[<ffffffff8160da60>] ? bit_wait_timeout+0x90/0x90
[<ffffffff8160d1f2>] ? schedule+0x32/0x80
[<ffffffff81610729>] ? schedule_timeout+0x249/0x300
[<ffffffff81336486>] ? __radix_tree_lookup+0x76/0xe0
***
[<ffffffff8101b7d1>] ? xen_clocksource_get_cycles+0x11/0x20
[<ffffffff8160da60>] ? bit_wait_timeout+0x90/0x90
[<ffffffff8160ca74>] ? io_schedule_timeout+0xb4/0x130
[<ffffffff810bb5e7>] ? prepare_to_wait+0x57/0x80
[<ffffffff8160da77>] ? bit_wait_io+0x17/0x60
[<ffffffff8160d56c>] ? __wait_on_bit+0x5c/0x90
[<ffffffffc00f290b>] ? __jbd2_journal_file_buffer+0xcb/0x180 [jbd2]
[<ffffffff8160da60>] ? bit_wait_timeout+0x90/0x90
[<ffffffff8160d6ce>] ? out_of_line_wait_on_bit+0x7e/0xa0
[<ffffffff810bb910>] ? autoremove_wake_function+0x40/0x40
[<ffffffffc00f2bc8>] ? do_get_write_access+0x208/0x420 [jbd2]
[<ffffffffc00f2e0e>] ? jbd2_journal_get_write_access+0x2e/0x60 [jbd2]
[<ffffffffc02c78a6>] ? __ext4_journal_get_write_access+0x36/0x70 [ext4]
[<ffffffffc02a3913>] ? ext4_orphan_add+0xd3/0x230 [ext4]
[<ffffffffc0296b4a>] ? ext4_mark_inode_dirty+0x6a/0x200 [ext4]
[<ffffffffc02a4b8a>] ? ext4_unlink+0x36a/0x380 [ext4]
[<ffffffff81211677>] ? vfs_unlink+0xe7/0x180
[<ffffffff81214439>] ? do_unlinkat+0x289/0x300
[<ffffffff81611abb>] ? system_call_fast_compare_end+0xc/0x9b
This does not look normal to me or did I miss something?
Where can I get more information on why there is no progress for 300s,
what should I do to debug which task is waiting for what?
The traces of the of other CPUs look normal to me: the one posted first
above is the shortest, in all other cases they were sooner or later
waiting for IO (my interpretation, but I can post them if necessary.)
This problem occurs since the upgrade of the Linux kernel inside the VM
from 4.1.x to 4.9.32 and now 4.9.52.
Any help is appreciated.
Philipp Hahn
--
Philipp Hahn
Open Source Software Engineer
Univention GmbH
be open.
Mary-Somerville-Str. 1
D-28359 Bremen
Tel.: +49 421 22232-0
Fax : +49 421 22232-99
h...@univention.de
http://www.univention.de/
Geschäftsführer: Peter H. Ganten
HRB 20755 Amtsgericht Bremen
Steuer-Nr.: 71-597-02876
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
https://lists.xen.org/xen-devel
