Discussion:
4.9.52: INFO: task XXX blocked for more than 300 seconds.
(too old to reply)
Philipp Hahn
2017-10-04 18:26:27 UTC
Permalink
Hello,

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
[<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
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
[<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
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
ffff8801bb832201 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffff8801f4a02ec0 0000000000000001 ffffffff810bc280 ffff8801f4a02ec0
ffff8801f4a02ec0 c0a995961d41240f addce6dcadd009c9 0000000000000000
[<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
0000000000000001 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffff8801f4a24f00 0000000000000003 ffffffff810bc280 ffff8801f4a24f00
ffff8801f4a24f00 77816deb133b9979 addce6dcadd009c9 0000000000000000
[<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
0000000000000001 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffffffff81c0e540 0000000000000000 ffffffff810bc280 ffffffff81c0e540
ffffffff81c0e540 ebeac214e330bd3f addce6dcadd009c9 ffffffffffffffff
[<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
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
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
[<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
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
[<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
***@univention.de

http://www.univention.de/
Geschäftsführer: Peter H. Ganten
HRB 20755 Amtsgericht Bremen
Steuer-Nr.: 71-597-02876
Jan Beulich
2017-10-05 10:12:58 UTC
Permalink
Post by Philipp Hahn
Hello,
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
[<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
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
[<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
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
ffff8801bb832201 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffff8801f4a02ec0 0000000000000001 ffffffff810bc280 ffff8801f4a02ec0
ffff8801f4a02ec0 c0a995961d41240f addce6dcadd009c9 0000000000000000
[<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
0000000000000001 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffff8801f4a24f00 0000000000000003 ffffffff810bc280 ffff8801f4a24f00
ffff8801f4a24f00 77816deb133b9979 addce6dcadd009c9 0000000000000000
[<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
0000000000000001 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffffffff81c0e540 0000000000000000 ffffffff810bc280 ffffffff81c0e540
ffffffff81c0e540 ebeac214e330bd3f addce6dcadd009c9 ffffffffffffffff
[<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
Hence the question marks ahead of the stack entries: What you see
there are likely leftovers from prior call trees. It just so happens
that the old return address slots haven't got overwritten yet. You
need to first sanitize the stack trace e.g. by having the kernel
dump more of the stack in raw hex form, and then looking at the
disassembly to figure out how large each stack frame is, starting
at the top-most address (i.e. the one in RIP).

Jan
Philipp Hahn
2017-10-05 12:04:44 UTC
Permalink
Hello Jan,

thank you for you answer.
Post by Jan Beulich
Post by Philipp Hahn
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
[<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
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
[<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
...
Post by Jan Beulich
Post by Philipp Hahn
Looking at the dis-assembly of xen_clocksource_get_cycles() in
arch/x86/xen/time.c I see no path how that should call
Hence the question marks ahead of the stack entries: What you see
there are likely leftovers from prior call trees. It just so happens
that the old return address slots haven't got overwritten yet. You
need to first sanitize the stack trace e.g. by having the kernel
dump more of the stack in raw hex form, and then looking at the
disassembly to figure out how large each stack frame is, starting
at the top-most address (i.e. the one in RIP).
That explains the strange call trace for me, thank you for the
enlightenment.
Post by Jan Beulich
Post by Philipp Hahn
INFO: task btrfs-transacti:522 blocked for more than 300 seconds.
[...]
Post by Philipp Hahn
INFO: task smbd:20101 blocked for more than 300 seconds.
[...]
Post by Philipp Hahn
This does not look normal to me or did I miss something?
So I see that both of the stuck processes listed above (smbd and
btrfs-*) are disk related processes. Might I ask how many disk/nics
(PV) do you have attached to this DomU, and how many queues does each
have?
Nothing special configured, how would I best fetch that info?


Which leads me back to my original problem: How can I diagnose *why* the
task is blocked for that time? From my understanding this can happen if
IO is too slow and task just have to wait for too long. ¹
Even if IO is slow the system should stabilize itself when no new IO is
generated and the old one has been processed, right? So looking at
`vmstat` or `blktrace` should tell me, that Xen/Linux/whatever is busy
with IO and it is simply not fast enough to keep up with the load.

Thanks again, but any hint how to diagnose this does help.

Philipp

¹
<https://www.blackmoreops.com/2014/09/22/linux-kernel-panic-issue-fix-hung_task_timeout_secs-blocked-120-seconds-problem/>
Roger Pau Monné
2017-10-05 10:38:37 UTC
Permalink
Post by Philipp Hahn
INFO: task btrfs-transacti:522 blocked for more than 300 seconds.
[...]
Post by Philipp Hahn
INFO: task smbd:20101 blocked for more than 300 seconds.
[...]
Post by Philipp Hahn
This does not look normal to me or did I miss something?
So I see that both of the stuck processes listed above (smbd and
btrfs-*) are disk related processes. Might I ask how many disk/nics
(PV) do you have attached to this DomU, and how many queues does each
have?

Thanks, Roger.
Konrad Rzeszutek Wilk
2017-10-05 13:20:16 UTC
Permalink
Post by Philipp Hahn
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?
Post by Philipp Hahn
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
[<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
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
[<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
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
ffff8801bb832201 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffff8801f4a02ec0 0000000000000001 ffffffff810bc280 ffff8801f4a02ec0
ffff8801f4a02ec0 c0a995961d41240f addce6dcadd009c9 0000000000000000
[<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
0000000000000001 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffff8801f4a24f00 0000000000000003 ffffffff810bc280 ffff8801f4a24f00
ffff8801f4a24f00 77816deb133b9979 addce6dcadd009c9 0000000000000000
[<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
0000000000000001 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffffffff81c0e540 0000000000000000 ffffffff810bc280 ffffffff81c0e540
ffffffff81c0e540 ebeac214e330bd3f addce6dcadd009c9 ffffffffffffffff
[<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
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
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
[<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
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
[<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
http://www.univention.de/
Geschäftsführer: Peter H. Ganten
HRB 20755 Amtsgericht Bremen
Steuer-Nr.: 71-597-02876
_______________________________________________
Xen-devel mailing list
https://lists.xen.org/xen-devel
Ankur Arora
2017-10-05 17:59:28 UTC
Permalink
Post by Konrad Rzeszutek Wilk
Post by Philipp Hahn
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?
Post by Philipp Hahn
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
[<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
Post by Konrad Rzeszutek Wilk
Post by Philipp Hahn
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
[<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
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
ffff8801bb832201 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffff8801f4a02ec0 0000000000000001 ffffffff810bc280 ffff8801f4a02ec0
ffff8801f4a02ec0 c0a995961d41240f addce6dcadd009c9 0000000000000000
[<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
0000000000000001 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffff8801f4a24f00 0000000000000003 ffffffff810bc280 ffff8801f4a24f00
ffff8801f4a24f00 77816deb133b9979 addce6dcadd009c9 0000000000000000
[<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
0000000000000001 0000000000000001 ffffffff8101b55c ffffffff81611ec8
ffffffff81c0e540 0000000000000000 ffffffff810bc280 ffffffff81c0e540
ffffffff81c0e540 ebeac214e330bd3f addce6dcadd009c9 ffffffffffffffff
[<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
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
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
[<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
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
[<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
http://www.univention.de/
Geschäftsführer: Peter H. Ganten
HRB 20755 Amtsgericht Bremen
Steuer-Nr.: 71-597-02876
_______________________________________________
Xen-devel mailing list
https://lists.xen.org/xen-devel
Philipp Hahn
2017-10-19 14:34:13 UTC
Permalink
Hello Ankur,
...
Post by Ankur Arora
Post by Konrad Rzeszutek Wilk
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?
Post by Philipp Hahn
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
  [<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/
I built a new kernel, for which I picked that patch on top of 4.9.56. We
are currently testing that, but it crashed again yesterday evening. Here
Post by Ankur Arora
INFO: task systemd:1 blocked for more than 120 seconds.
Not tainted 4.9.0-ucs105-amd64 #1 Debian 4.9.30-2A~4.2.0.201710161640
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
systemd D 0 1 0 0x00000000
ffff8801f1797c00 0000000000000000 ffffffff81c0e540 ffff8801f4956040
ffff8801f5a187c0 ffffc90040c4f880 ffffffff8160ebbd ffffffff81186295
ffffffff81350b39 0000000002cebf80 ffffffff811863c8 ffff8801f4956040
[<ffffffff8160ebbd>] ? __schedule+0x23d/0x6d0
[<ffffffff81186295>] ? move_freepages+0x95/0xd0
[<ffffffff81350b39>] ? list_del+0x9/0x20
[<ffffffff811863c8>] ? __rmqueue+0x88/0x3e0
[<ffffffff8160f082>] ? schedule+0x32/0x80
[<ffffffff8161255c>] ? schedule_timeout+0x1ec/0x360
[<ffffffff81187530>] ? get_page_from_freelist+0x350/0xad0
[<ffffffff8160e904>] ? io_schedule_timeout+0xb4/0x130
[<ffffffff81364fd4>] ? __sbitmap_queue_get+0x24/0x90
[<ffffffff813114f9>] ? bt_get.isra.6+0x129/0x1c0
[<ffffffff81350b39>] ? list_del+0x9/0x20
[<ffffffff810bba00>] ? wake_up_atomic_t+0x30/0x30
[<ffffffff81311843>] ? blk_mq_get_tag+0x23/0x90
[<ffffffff8130d1aa>] ? __blk_mq_alloc_request+0x1a/0x220
[<ffffffff8130dffd>] ? blk_mq_map_request+0xcd/0x170
[<ffffffff8131016a>] ? blk_sq_make_request+0xca/0x4c0
[<ffffffff81303e1a>] ? generic_make_request_checks+0x22a/0x4f0
[<ffffffff81304761>] ? generic_make_request+0x121/0x2c0
[<ffffffff8117e823>] ? __add_to_page_cache_locked+0x183/0x230
[<ffffffff81304976>] ? submit_bio+0x76/0x150
[<ffffffff8117e964>] ? add_to_page_cache_lru+0x84/0xe0
[<ffffffffc017b9d9>] ? ext4_mpage_readpages+0x2b9/0x8b0 [ext4]
[<ffffffff811d94fa>] ? alloc_pages_current+0x8a/0x110
[<ffffffff8118e745>] ? __do_page_cache_readahead+0x195/0x240
[<ffffffff8117f627>] ? pagecache_get_page+0x27/0x2b0
[<ffffffff811818e6>] ? filemap_fault+0x276/0x590
[<ffffffffc0138491>] ? ext4_filemap_fault+0x31/0x50 [ext4]
[<ffffffff811b23a4>] ? __do_fault+0x84/0x190
[<ffffffff811b783e>] ? handle_mm_fault+0xede/0x1680
[<ffffffff8124d25e>] ? ep_poll+0x13e/0x360
[<ffffffff8105feda>] ? __do_page_fault+0x26a/0x500
[<ffffffff81205ba2>] ? SyS_read+0x52/0xc0
[<ffffffff81614d58>] ? page_fault+0x28/0x30
I haven't been able to get the address of the queue object yet to get
its state. (timeout for today)
Post by Ankur Arora
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.
As soon as the bug occurs, we can no longer access the VM via ssh or the
Xen (serial) console: the connection stalls after entering 2-3 characters.

I have a Xen crash-dump file of one such crash, but following
/sys/block/xvd?/mq/*/tags manually to get the kobject address using
"crash" (gdb) is very time consuming. So far I only did it once for
xvda, but I have to to that for the other 15 block devices as well to
find one culprit.

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
***@univention.de

http://www.univention.de/
GeschÀftsfÌhrer: Peter H. Ganten
HRB 20755 Amtsgericht Bremen
Steuer-Nr.: 71-597-0287

Continue reading on narkive:
Loading...