<div dir="ltr">Hi Matej,<div><br></div><div>Can you change the values(both on compute and instance node) and see if soft lock-ups generated again? There are two approaches; one decreasing and the other increasing the cache. </div><div><br></div><div>vm.dirty_background_ratio = 5</div><div>vm.dirty_ratio = 10</div><div><br></div><div>If I/O & Cache is not the source of the problem, we should focus on CPU settings or kernel. </div><div><br></div><div>For example, you can try to use a different kernel (before 3.18.1) and see if it happens again? </div><div><br></div><div>Thanks,</div><div>Erhan</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Sun, Jan 4, 2015 at 8:39 PM, Matej Mailing <span dir="ltr"><<a href="mailto:mailing@tam.si" target="_blank">mailing@tam.si</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="HOEnZb"><div class="h5">2015-01-04 17:10 GMT+01:00 Erhan Ekici <<a href="mailto:erhan.ekici@gmail.com">erhan.ekici@gmail.com</a>>:<br>
> Hi Matej,<br>
><br>
> I am not sure but most of the soft lock-up messages generated due to I/O<br>
> issues. From your log entries, I see mysqld issues as well as others:<br>
><br>
> Jan 3 10:41:44 postar kernel: [303154.352793] NMI watchdog: BUG: soft<br>
> lockup - CPU#3 stuck for 45s! [mysqld:4601]<br>
> ....<br>
> Jan 3 10:44:00 postar kernel: [303290.052498] INFO: task mysqld:2290<br>
> blocked for more than 120 seconds.<br>
> Jan 3 10:41:44 postar kernel: [303154.352958] CPU: 3 PID: 4601 Comm: mysqld<br>
> Not tainted 3.18.1-031801-generic #201412170637<br>
> ....<br>
> Jan 3 10:44:00 postar kernel: [303290.052499] Tainted: G L<br>
> 3.18.1-031801-generic #201412170637<br>
> Jan 3 10:44:00 postar kernel: [303290.052499] "echo 0 ><br>
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.<br>
> Jan 3 10:44:00 postar kernel: [303290.052502] mysqld D<br>
> 0000000000000002 0 2290 1 0x00000000<br>
><br>
> Can you post the output of the following command on both instance nodes OS<br>
> and compute node OS and memory of Compute node and instances?<br>
><br>
> [user@node] sudo sysctl -a | grep dirty<br>
><br>
> vm.dirty_background_bytes = 0<br>
> vm.dirty_background_ratio = 10<br>
> vm.dirty_bytes = 0<br>
> vm.dirty_expire_centisecs = 3000<br>
> vm.dirty_ratio = 20<br>
> vm.dirty_writeback_centisecs = 500<br>
><br>
><br>
> Erhan,<br>
<br>
</div></div>Hello Erhan,<br>
<br>
instance node output:<br>
<br>
error: permission denied on key 'net.ipv4.route.flush'<br>
error: permission denied on key 'net.ipv6.route.flush'<br>
error: permission denied on key 'vm.compact_memory'<br>
<span class="">vm.dirty_background_bytes = 0<br>
vm.dirty_background_ratio = 10<br>
vm.dirty_bytes = 0<br>
vm.dirty_expire_centisecs = 3000<br>
vm.dirty_ratio = 20<br>
vm.dirty_writeback_centisecs = 500<br>
<br>
</span>Mem: 8175996k total, 4105708k used, 4070288k free, 218552k buffers<br>
<br>
<br>
compute node output:<br>
<span class="">vm.dirty_background_bytes = 0<br>
vm.dirty_background_ratio = 10<br>
vm.dirty_bytes = 0<br>
vm.dirty_expire_centisecs = 3000<br>
vm.dirty_ratio = 20<br>
vm.dirty_writeback_centisecs = 500<br>
<br>
</span>KiB Mem: 16432492 total, 16254932 used, 177560 free, 9316 buffers<br>
<br>
Lock-ups happen with different processes, above-mentioned mysqld is<br>
just an example.<br>
<br>
Thanks,<br>
Matej<br>
<div class="HOEnZb"><div class="h5"><br>
<br>
><br>
> On Sun, Jan 4, 2015 at 2:36 PM, Matej Mailing <<a href="mailto:mailing@tam.si">mailing@tam.si</a>> wrote:<br>
>><br>
>> 2015-01-03 17:56 GMT+01:00 John Griffith <<a href="mailto:john.griffith@solidfire.com">john.griffith@solidfire.com</a>>:<br>
>> > On Sat, Jan 3, 2015 at 5:05 AM, Matej Mailing <<a href="mailto:mailing@tam.si">mailing@tam.si</a>> wrote:<br>
>> >> Hi,<br>
>> >><br>
>> >> we are experiencing randomly-timed soft lockup messages in different<br>
>> >> instances (running CentOS, Ubuntu, etc.) with different processes and<br>
>> >> on different compute nodes. I suspect that access to the cinder<br>
>> >> storage via NFS could be the cause of issue, but then perhaps all the<br>
>> >> instances would trigger the error message on the same time? Currently<br>
>> >> they don't and no higher access loads are repoted on the NFS server<br>
>> >> itself, neither the load is higher at those times ...<br>
>> >> What are the best methods to debug this error? Any suggestions and<br>
>> >> expeiences on fixing it will be very welcome :-)<br>
>> >><br>
>> >> Thanks,<br>
>> >> Matej<br>
>> >><br>
>> >> _______________________________________________<br>
>> >> Mailing list:<br>
>> >> <a href="http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack" target="_blank">http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack</a><br>
>> >> Post to : <a href="mailto:openstack@lists.openstack.org">openstack@lists.openstack.org</a><br>
>> >> Unsubscribe :<br>
>> >> <a href="http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack" target="_blank">http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack</a><br>
>> ><br>
>> > Hi Matej,<br>
>> ><br>
>> > I'm assuming the kernel logs indicate NFS as the culprit here? What<br>
>> > sort of IO load are you seeing on the system when these are<br>
>> > encountered?<br>
>> ><br>
>> > A quick search on "soft lockup nfs" has a pretty lengthy list of<br>
>> > results including some setting recommendations etc. Maybe start<br>
>> > there?<br>
>> ><br>
>> > Thanks,<br>
>> > John<br>
>><br>
>> Hello John,<br>
>><br>
>> thank you very much for your answer. I can't find anything at all in<br>
>> the compute node's logs and my NFS-idea is just a guess<br>
>> actually.Example entry from Ubuntu instances is like:<br>
>><br>
>> Jan 3 10:41:44 postar kernel: [303154.352793] NMI watchdog: BUG: soft<br>
>> lockup - CPU#3 stuck for 45s! [mysqld:4601]<br>
>> Jan 3 10:41:44 postar kernel: [303154.352890] Modules linked in:<br>
>> xt_hl ip6t_rt nf_conntrack_ipv6 nf_defrag_ipv6 ipt_REJECT<br>
>> nf_reject_ipv4 xt_limit xt_tcpudp xt_addrtype nf_conntrack_ipv4<br>
>> nf_defrag_ipv4 xt_state ip6table_filter ip6_tables nfsd nfs_acl<br>
>> auth_rpcgss nf_conntrack_netbios_ns<br>
>> nf_conntrack_broadcast nfs nf_nat_ftp nf_nat ppdev nf_conntrack_ftp<br>
>> nf_conntrack fscache parport_pc parport lockd joydev pvpanic<br>
>> iptable_filter cirrus ip_tables 8250_fintek ttm psmouse drm_kms_helper<br>
>> sunrpc x_tables serio_raw hid_generic drm grace mac_hid sysimgblt<br>
>> sysfillrect syscopyarea<br>
>> i2c_piix4 usbhid hid floppy<br>
>> Jan 3 10:41:44 postar kernel: [303154.352958] CPU: 3 PID: 4601 Comm:<br>
>> mysqld Not tainted 3.18.1-031801-generic #201412170637<br>
>> Jan 3 10:41:44 postar kernel: [303154.352961] Hardware name:<br>
>> OpenStack Foundation OpenStack Nova, BIOS Bochs 01/01/2011<br>
>> Jan 3 10:41:44 postar kernel: [303154.352964] task: ffff880231b63c00<br>
>> ti: ffff8801e6014000 task.ti: ffff8801e6014000<br>
>> Jan 3 10:41:44 postar kernel: [303154.352966] RIP:<br>
>> 0010:[<ffffffff813a97dc>] [<ffffffff813a97dc>]<br>
>> copy_user_generic_string+0x2c/0x40<br>
>> Jan 3 10:41:44 postar kernel: [303154.352979] RSP:<br>
>> 0018:ffff8801e6017c90 EFLAGS: 00010246<br>
>> Jan 3 10:41:44 postar kernel: [303154.352981] RAX: 00000000a2418000<br>
>> RBX: ffff8801e6017ea0 RCX: 0000000000000200<br>
>> Jan 3 10:41:44 postar kernel: [303154.352983] RDX: 0000000000000000<br>
>> RSI: ffff8800a2418000 RDI: 00007fd365b90000<br>
>> Jan 3 10:41:44 postar kernel: [303154.352985] RBP: ffff8801e6017d08<br>
>> R08: ffffea000289061c R09: ffff8801e6017ca0<br>
>> Jan 3 10:41:44 postar kernel: [303154.352987] R10: ffff8800a5c1b258<br>
>> R11: 0000000000000293 R12: 0000000000000000<br>
>> Jan 3 10:41:44 postar kernel: [303154.352989] R13: ffff8801e6017ec8<br>
>> R14: 0000000000001000 R15: 00007fd365b90000<br>
>> Jan 3 10:41:44 postar kernel: [303154.352995] FS:<br>
>> 00007fd36c28e700(0000) GS:ffff88023fd80000(0000)<br>
>> knlGS:0000000000000000<br>
>> Jan 3 10:41:44 postar kernel: [303154.352998] CS: 0010 DS: 0000 ES:<br>
>> 0000 CR0: 0000000080050033<br>
>> Jan 3 10:41:44 postar kernel: [303154.353000] CR2: 0000000002b9e003<br>
>> CR3: 00000002317ee000 CR4: 00000000000006e0<br>
>> Jan 3 10:41:44 postar kernel: [303154.353014] Stack:<br>
>> Jan 3 10:41:44 postar kernel: [303154.353016] ffffffff811a0f75<br>
>> ffff8801e6017d88 ffff8800a5c1b258 ffff8801e6017cc8<br>
>> Jan 3 10:41:44 postar kernel: [303154.353019] ffffffff8117864e<br>
>> ffff8800a2418000 ffffea0002890600 0000000000001000<br>
>> Jan 3 10:41:44 postar kernel: [303154.353023] ffff8800a2418000<br>
>> 0000000000000000 ffffea0002890600 ffff880231e4b930<br>
>> Jan 3 10:41:44 postar kernel: [303154.353026] Call Trace:<br>
>> Jan 3 10:41:44 postar kernel: [303154.353034] [<ffffffff811a0f75>] ?<br>
>> copy_page_to_iter_iovec+0xe5/0x300<br>
>> Jan 3 10:41:44 postar kernel: [303154.353040] [<ffffffff8117864e>] ?<br>
>> find_get_entry+0x1e/0x90<br>
>> Jan 3 10:41:44 postar kernel: [303154.353044] [<ffffffff811a14a6>]<br>
>> copy_page_to_iter+0x16/0x70<br>
>> Jan 3 10:41:44 postar kernel: [303154.353047] [<ffffffff81179428>]<br>
>> do_generic_file_read+0x1f8/0x490<br>
>> Jan 3 10:41:44 postar kernel: [303154.353051] [<ffffffff8117a234>]<br>
>> generic_file_read_iter+0xf4/0x150<br>
>> Jan 3 10:41:44 postar kernel: [303154.353056] [<ffffffff810aade1>] ?<br>
>> update_curr+0x141/0x1f0<br>
>> Jan 3 10:41:44 postar kernel: [303154.353060] [<ffffffff810efcd8>] ?<br>
>> get_futex_key+0x1f8/0x2e0<br>
>> Jan 3 10:41:44 postar kernel: [303154.353065] [<ffffffff811eef28>]<br>
>> new_sync_read+0x78/0xb0<br>
>> Jan 3 10:41:44 postar kernel: [303154.353068] [<ffffffff811f013b>]<br>
>> vfs_read+0xab/0x180<br>
>> Jan 3 10:41:44 postar kernel: [303154.353071] [<ffffffff811f0402>]<br>
>> SyS_pread64+0x92/0xa0<br>
>> Jan 3 10:41:44 postar kernel: [303154.353077] [<ffffffff817b376d>]<br>
>> system_call_fastpath+0x16/0x1b<br>
>> Jan 3 10:41:44 postar kernel: [303154.353079] Code: 66 90 83 fa 08 72<br>
>> 27 89 f9 83 e1 07 74 15 83 e9 08 f7 d9 29 ca 8a 06 88 07 48 ff c6 48<br>
>> ff c7 ff c9 75 f2 89 d1 c1 e9 03 83 e2 07 <f3> 48 a5 89 d1 f3 a4 31 c0<br>
>> 66 66 90 c3 0f 1f 80 00 00 00 00 66<br>
>><br>
>><br>
>> and:<br>
>><br>
>> Jan 3 10:44:00 postar kernel: [303164.436029] INFO: rcu_sched<br>
>> detected stalls on CPUs/tasks: { 3} (detected by 0, t=33923 jiffies,<br>
>> g=1793081, c=1793080, q=0)<br>
>> Jan 3 10:44:00 postar kernel: [303164.436029] Task dump for CPU 3:<br>
>> Jan 3 10:44:00 postar kernel: [303164.436029] mysqld R<br>
>> running task 0 4601 1 0x00000008<br>
>> Jan 3 10:44:00 postar kernel: [303164.436029] 0000000000000001<br>
>> 00007fd36286c000 0000000000004000 0000000000004000<br>
>> Jan 3 10:44:00 postar kernel: [303164.436029] 00007fd36286c000<br>
>> ffff8801e6017f28 ffffffff811f013b 00007fd36c28ba80<br>
>> Jan 3 10:44:00 postar kernel: [303164.436029] ffff8802316eaf01<br>
>> ffff8802316eaf00 00007fd36286c000 0000000000004000<br>
>> Jan 3 10:44:00 postar kernel: [303164.436029] Call Trace:<br>
>> Jan 3 10:44:00 postar kernel: [303164.436029] [<ffffffff811f013b>] ?<br>
>> vfs_read+0xab/0x180<br>
>> Jan 3 10:44:00 postar kernel: [303164.436029] [<ffffffff811f0402>] ?<br>
>> SyS_pread64+0x92/0xa0<br>
>> Jan 3 10:44:00 postar kernel: [303164.436029] [<ffffffff817b376d>] ?<br>
>> system_call_fastpath+0x16/0x1b<br>
>> Jan 3 10:44:00 postar kernel: [303290.052393] INFO: task<br>
>> jbd2/vda1-8:256 blocked for more than 120 seconds.<br>
>> Jan 3 10:44:00 postar kernel: [303290.052395] Tainted: G<br>
>> L 3.18.1-031801-generic #201412170637<br>
>> Jan 3 10:44:00 postar kernel: [303290.052396] "echo 0 ><br>
>> /proc/sys/kernel/hung_task_timeout_secs" disables this message.<br>
>> Jan 3 10:44:00 postar kernel: [303290.052399] jbd2/vda1-8 D<br>
>> 0000000000000002 0 256 2 0x00000000<br>
>> Jan 3 10:44:00 postar kernel: [303290.052402] ffff88023170b6a8<br>
>> 0000000000000046 ffff88023170b648 0000000000f2f754<br>
>> Jan 3 10:44:00 postar kernel: [303290.052404] ffff88023170bfd8<br>
>> 0000000000013640 ffff8800baef5f80 0000000000013640<br>
>> Jan 3 10:44:00 postar kernel: [303290.052406] ffff8802342ab200<br>
>> ffff880231b64600 ffff88023170b678 ffff88023fd13f40<br>
>> Jan 3 10:44:00 postar kernel: [303290.052407] Call Trace:<br>
>> Jan 3 10:44:00 postar kernel: [303290.052413] [<ffffffff817af549>]<br>
>> schedule+0x29/0x70<br>
>> Jan 3 10:44:00 postar kernel: [303290.052415] [<ffffffff817af61f>]<br>
>> io_schedule+0x8f/0xd0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052419] [<ffffffff81379f30>]<br>
>> bt_get+0xf0/0x180<br>
>> Jan 3 10:44:00 postar kernel: [303290.052423] [<ffffffff810b4bd0>] ?<br>
>> prepare_to_wait_event+0x100/0x100<br>
>> Jan 3 10:44:00 postar kernel: [303290.052425] [<ffffffff8137a2f2>]<br>
>> blk_mq_get_tag+0x82/0xd0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052428] [<ffffffff813762da>]<br>
>> __blk_mq_alloc_request+0x2a/0xb0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052430] [<ffffffff81377d72>]<br>
>> blk_mq_map_request+0x182/0x1f0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052432] [<ffffffff81377a36>] ?<br>
>> __blk_mq_run_hw_queue+0xf6/0x260<br>
>> Jan 3 10:44:00 postar kernel: [303290.052434] [<ffffffff81378446>]<br>
>> blk_sq_make_request+0x96/0x310<br>
>> Jan 3 10:44:00 postar kernel: [303290.052438] [<ffffffff81369c65>]<br>
>> generic_make_request.part.75+0x75/0xb0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052440] [<ffffffff8136a288>]<br>
>> generic_make_request+0x68/0x70<br>
>> Jan 3 10:44:00 postar kernel: [303290.052442] [<ffffffff8136a316>]<br>
>> submit_bio+0x86/0x160<br>
>> Jan 3 10:44:00 postar kernel: [303290.052446] [<ffffffff81177789>] ?<br>
>> unlock_page+0x69/0x70<br>
>> Jan 3 10:44:00 postar kernel: [303290.052449] [<ffffffff81278b39>]<br>
>> ext4_io_submit+0x29/0x50<br>
>> Jan 3 10:44:00 postar kernel: [303290.052451] [<ffffffff8127427b>]<br>
>> ext4_writepage+0xcb/0x240<br>
>> Jan 3 10:44:00 postar kernel: [303290.052454] [<ffffffff811b16c0>] ?<br>
>> SyS_msync+0x230/0x230<br>
>> Jan 3 10:44:00 postar kernel: [303290.052457] [<ffffffff81182b87>]<br>
>> __writepage+0x17/0x50<br>
>> Jan 3 10:44:00 postar kernel: [303290.052460] [<ffffffff8118323a>]<br>
>> write_cache_pages+0x20a/0x470<br>
>> Jan 3 10:44:00 postar kernel: [303290.052462] [<ffffffff81182b70>] ?<br>
>> set_page_dirty_lock+0x60/0x60<br>
>> Jan 3 10:44:00 postar kernel: [303290.052464] [<ffffffff811834ea>]<br>
>> generic_writepages+0x4a/0x70<br>
>> Jan 3 10:44:00 postar kernel: [303290.052468] [<ffffffff812bb73f>]<br>
>> journal_submit_data_buffers+0xcf/0x180<br>
>> Jan 3 10:44:00 postar kernel: [303290.052470] [<ffffffff812bc1c4>]<br>
>> jbd2_journal_commit_transaction+0x394/0x1440<br>
>> Jan 3 10:44:00 postar kernel: [303290.052474] [<ffffffff812c09b3>]<br>
>> kjournald2+0xb3/0x230<br>
>> Jan 3 10:44:00 postar kernel: [303290.052476] [<ffffffff810b4bd0>] ?<br>
>> prepare_to_wait_event+0x100/0x100<br>
>> Jan 3 10:44:00 postar kernel: [303290.052478] [<ffffffff812c0900>] ?<br>
>> commit_timeout+0x10/0x10<br>
>> Jan 3 10:44:00 postar kernel: [303290.052481] [<ffffffff81093a09>]<br>
>> kthread+0xc9/0xe0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052483] [<ffffffff81093940>] ?<br>
>> flush_kthread_worker+0x90/0x90<br>
>> Jan 3 10:44:00 postar kernel: [303290.052485] [<ffffffff817b36bc>]<br>
>> ret_from_fork+0x7c/0xb0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052487] [<ffffffff81093940>] ?<br>
>> flush_kthread_worker+0x90/0x90<br>
>> Jan 3 10:44:00 postar kernel: [303290.052498] INFO: task mysqld:2290<br>
>> blocked for more than 120 seconds.<br>
>> Jan 3 10:44:00 postar kernel: [303290.052499] Tainted: G<br>
>> L 3.18.1-031801-generic #201412170637<br>
>> Jan 3 10:44:00 postar kernel: [303290.052499] "echo 0 ><br>
>> /proc/sys/kernel/hung_task_timeout_secs" disables this message.<br>
>> Jan 3 10:44:00 postar kernel: [303290.052502] mysqld D<br>
>> 0000000000000002 0 2290 1 0x00000000<br>
>> Jan 3 10:44:00 postar kernel: [303290.052504] ffff88023122b9c8<br>
>> 0000000000000082 ffff880200000002 0000000000f2f748<br>
>> Jan 3 10:44:00 postar kernel: [303290.052506] ffff88023122bfd8<br>
>> 0000000000013640 ffff880231b98380 0000000000013640<br>
>> Jan 3 10:44:00 postar kernel: [303290.052508] ffff880037ab3200<br>
>> ffff880233142800 ffff88023122b998 ffff88023fd13f40<br>
>> Jan 3 10:44:00 postar kernel: [303290.052509] Call Trace:<br>
>> Jan 3 10:44:00 postar kernel: [303290.052511] [<ffffffff817af549>]<br>
>> schedule+0x29/0x70<br>
>> Jan 3 10:44:00 postar kernel: [303290.052531] [<ffffffff817af61f>]<br>
>> io_schedule+0x8f/0xd0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052534] [<ffffffff81379f30>]<br>
>> bt_get+0xf0/0x180<br>
>> Jan 3 10:44:00 postar kernel: [303290.052536] [<ffffffff810b4bd0>] ?<br>
>> prepare_to_wait_event+0x100/0x100<br>
>> Jan 3 10:44:00 postar kernel: [303290.052538] [<ffffffff8137a2f2>]<br>
>> blk_mq_get_tag+0x82/0xd0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052540] [<ffffffff813762da>]<br>
>> __blk_mq_alloc_request+0x2a/0xb0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052542] [<ffffffff81377d72>]<br>
>> blk_mq_map_request+0x182/0x1f0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052545] [<ffffffff81378446>]<br>
>> blk_sq_make_request+0x96/0x310<br>
>> Jan 3 10:44:00 postar kernel: [303290.052547] [<ffffffff81369c65>]<br>
>> generic_make_request.part.75+0x75/0xb0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052549] [<ffffffff8136a288>]<br>
>> generic_make_request+0x68/0x70<br>
>> Jan 3 10:44:00 postar kernel: [303290.052551] [<ffffffff8136a316>]<br>
>> submit_bio+0x86/0x160<br>
>> Jan 3 10:44:00 postar kernel: [303290.052553] [<ffffffff812b940d>] ?<br>
>> jbd2__journal_start+0x4d/0x60<br>
>> Jan 3 10:44:00 postar kernel: [303290.052555] [<ffffffff81278b39>]<br>
>> ext4_io_submit+0x29/0x50<br>
>> Jan 3 10:44:00 postar kernel: [303290.052557] [<ffffffff81277446>]<br>
>> ext4_writepages+0x4f6/0x7b0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052560] [<ffffffff810efcd8>] ?<br>
>> get_futex_key+0x1f8/0x2e0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052563] [<ffffffff81184730>]<br>
>> do_writepages+0x20/0x40<br>
>> Jan 3 10:44:00 postar kernel: [303290.052565] [<ffffffff81179b29>]<br>
>> __filemap_fdatawrite_range+0x59/0x60<br>
>> Jan 3 10:44:00 postar kernel: [303290.052567] [<ffffffff81179b67>]<br>
>> filemap_write_and_wait_range+0x37/0x80<br>
>> Jan 3 10:44:00 postar kernel: [303290.052571] [<ffffffff8126c3a5>]<br>
>> ext4_sync_file+0x105/0x290<br>
>> Jan 3 10:44:00 postar kernel: [303290.052573] [<ffffffff811f0036>] ?<br>
>> vfs_write+0x196/0x1f0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052576] [<ffffffff8121faa8>]<br>
>> do_fsync+0x58/0x80<br>
>> Jan 3 10:44:00 postar kernel: [303290.052578] [<ffffffff8121fe70>]<br>
>> SyS_fsync+0x10/0x20<br>
>> Jan 3 10:44:00 postar kernel: [303290.052580] [<ffffffff817b376d>]<br>
>> system_call_fastpath+0x16/0x1b<br>
>> Jan 3 10:44:00 postar kernel: [303290.052590] INFO: task<br>
>> kworker/u8:1:22405 blocked for more than 120 seconds.<br>
>> Jan 3 10:44:00 postar kernel: [303290.052592] Tainted: G<br>
>> L 3.18.1-031801-generic #201412170637<br>
>> Jan 3 10:44:00 postar kernel: [303290.052592] "echo 0 ><br>
>> /proc/sys/kernel/hung_task_timeout_secs" disables this message.<br>
>> Jan 3 10:44:00 postar kernel: [303290.052595] kworker/u8:1 D<br>
>> 0000000000000002 0 22405 2 0x00000000<br>
>> Jan 3 10:44:00 postar kernel: [303290.052600] Workqueue: writeback<br>
>> bdi_writeback_workfn (flush-253:0)<br>
>> Jan 3 10:44:00 postar kernel: [303290.052602] ffff8801f38374c8<br>
>> 0000000000000046 ffff8801f38374b8 0000000000f2f754<br>
>> Jan 3 10:44:00 postar kernel: [303290.052604] ffff8801f3837fd8<br>
>> 0000000000013640 ffff8800baef5f80 0000000000013640<br>
>> Jan 3 10:44:00 postar kernel: [303290.052606] ffff880231b64600<br>
>> ffff8801f397d000 ffff8801f3837498 ffff88023fd13f40<br>
>> Jan 3 10:44:00 postar kernel: [303290.052607] Call Trace:<br>
>> Jan 3 10:44:00 postar kernel: [303290.052609] [<ffffffff817af549>]<br>
>> schedule+0x29/0x70<br>
>> Jan 3 10:44:00 postar kernel: [303290.052611] [<ffffffff817af61f>]<br>
>> io_schedule+0x8f/0xd0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052614] [<ffffffff81379f30>]<br>
>> bt_get+0xf0/0x180<br>
>> Jan 3 10:44:00 postar kernel: [303290.052616] [<ffffffff810b4bd0>] ?<br>
>> prepare_to_wait_event+0x100/0x100<br>
>> Jan 3 10:44:00 postar kernel: [303290.052618] [<ffffffff8137a2f2>]<br>
>> blk_mq_get_tag+0x82/0xd0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052620] [<ffffffff813762da>]<br>
>> __blk_mq_alloc_request+0x2a/0xb0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052622] [<ffffffff81377d72>]<br>
>> blk_mq_map_request+0x182/0x1f0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052626] [<ffffffff814692de>] ?<br>
>> alloc_indirect+0x1e/0x50<br>
>> Jan 3 10:44:00 postar kernel: [303290.052628] [<ffffffff81378446>]<br>
>> blk_sq_make_request+0x96/0x310<br>
>> Jan 3 10:44:00 postar kernel: [303290.052630] [<ffffffff81369c65>]<br>
>> generic_make_request.part.75+0x75/0xb0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052633] [<ffffffff8136a288>]<br>
>> generic_make_request+0x68/0x70<br>
>> Jan 3 10:44:00 postar kernel: [303290.052634] [<ffffffff8136a316>]<br>
>> submit_bio+0x86/0x160<br>
>> Jan 3 10:44:00 postar kernel: [303290.052638] [<ffffffff81364e5b>] ?<br>
>> bio_alloc_bioset+0xbb/0x220<br>
>> Jan 3 10:44:00 postar kernel: [303290.052641] [<ffffffff81223ff0>]<br>
>> _submit_bh+0x110/0x150<br>
>> Jan 3 10:44:00 postar kernel: [303290.052643] [<ffffffff81224040>]<br>
>> submit_bh+0x10/0x20<br>
>> Jan 3 10:44:00 postar kernel: [303290.052646] [<ffffffff81225cc0>]<br>
>> __block_write_full_page.constprop.35+0x1a0/0x380<br>
>> Jan 3 10:44:00 postar kernel: [303290.052648] [<ffffffff81226110>] ?<br>
>> I_BDEV+0x10/0x10<br>
>> Jan 3 10:44:00 postar kernel: [303290.052650] [<ffffffff81226110>] ?<br>
>> I_BDEV+0x10/0x10<br>
>> Jan 3 10:44:00 postar kernel: [303290.052652] [<ffffffff81226039>]<br>
>> block_write_full_page+0xa9/0xe0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052654] [<ffffffff81226b38>]<br>
>> blkdev_writepage+0x18/0x20<br>
>> Jan 3 10:44:00 postar kernel: [303290.052656] [<ffffffff81182b87>]<br>
>> __writepage+0x17/0x50<br>
>> Jan 3 10:44:00 postar kernel: [303290.052658] [<ffffffff8118323a>]<br>
>> write_cache_pages+0x20a/0x470<br>
>> Jan 3 10:44:00 postar kernel: [303290.052660] [<ffffffff81182b70>] ?<br>
>> set_page_dirty_lock+0x60/0x60<br>
>> Jan 3 10:44:00 postar kernel: [303290.052663] [<ffffffff811834ea>]<br>
>> generic_writepages+0x4a/0x70<br>
>> Jan 3 10:44:00 postar kernel: [303290.052665] [<ffffffff81184730>]<br>
>> do_writepages+0x20/0x40<br>
>> Jan 3 10:44:00 postar kernel: [303290.052668] [<ffffffff81217fe5>]<br>
>> __writeback_single_inode+0x45/0x1c0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052670] [<ffffffff812199be>]<br>
>> writeback_sb_inodes+0x22e/0x340<br>
>> Jan 3 10:44:00 postar kernel: [303290.052673] [<ffffffff81219b6e>]<br>
>> __writeback_inodes_wb+0x9e/0xd0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052675] [<ffffffff81219e2b>]<br>
>> wb_writeback+0x28b/0x330<br>
>> Jan 3 10:44:00 postar kernel: [303290.052678] [<ffffffff8120ac32>] ?<br>
>> get_nr_dirty_inodes+0x52/0x80<br>
>> Jan 3 10:44:00 postar kernel: [303290.052681] [<ffffffff81219f6f>]<br>
>> wb_check_old_data_flush+0x9f/0xb0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052683] [<ffffffff8121a0b4>]<br>
>> wb_do_writeback+0x134/0x1c0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052685] [<ffffffff810908bf>] ?<br>
>> set_worker_desc+0x6f/0x80<br>
>> Jan 3 10:44:00 postar kernel: [303290.052688] [<ffffffff8121c048>]<br>
>> bdi_writeback_workfn+0x78/0x1f0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052729] [<ffffffff8108d50e>]<br>
>> process_one_work+0x14e/0x460<br>
>> Jan 3 10:44:00 postar kernel: [303290.052732] [<ffffffff8108de8b>]<br>
>> worker_thread+0x11b/0x3f0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052735] [<ffffffff8108dd70>] ?<br>
>> create_worker+0x1e0/0x1e0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052737] [<ffffffff81093a09>]<br>
>> kthread+0xc9/0xe0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052739] [<ffffffff81093940>] ?<br>
>> flush_kthread_worker+0x90/0x90<br>
>> Jan 3 10:44:00 postar kernel: [303290.052741] [<ffffffff817b36bc>]<br>
>> ret_from_fork+0x7c/0xb0<br>
>> Jan 3 10:44:00 postar kernel: [303290.052743] [<ffffffff81093940>] ?<br>
>> flush_kthread_worker+0x90/0x90<br>
>><br>
>> The instance's qcow2 file is on a NFS share, mounted on a compute node.<br>
>><br>
>> Different processes are triggering the soft lock-up, what is<br>
>> interesting is that we see soft lock-ups showing up on the same time<br>
>> on all the instances running on the same compute node. I will examine<br>
>> iostat and top outputs closely when it happens, it's relatively hard<br>
>> to catch that moment since it happens for a relatively short period of<br>
>> time.<br>
>><br>
>> Thank you for any ideas in advance.<br>
>> Matej<br>
>><br>
>> _______________________________________________<br>
>> Mailing list:<br>
>> <a href="http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack" target="_blank">http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack</a><br>
>> Post to : <a href="mailto:openstack@lists.openstack.org">openstack@lists.openstack.org</a><br>
>> Unsubscribe :<br>
>> <a href="http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack" target="_blank">http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack</a><br>
><br>
><br>
</div></div></blockquote></div><br></div>