Re: INFO: task hung in ip6gre_exit_batch_net

[Kirill Tkhai]

On 08.06.2018 11:18, Dmitry Vyukov wrote:
> On Thu, Jun 7, 2018 at 9:59 PM, Kirill Tkhai <ktkhai@xxxxxxxxxxxxx> wrote:
>> On 07.06.2018 22:03, Dmitry Vyukov wrote:
>>> On Thu, Jun 7, 2018 at 8:54 PM, Kirill Tkhai <ktkhai@xxxxxxxxxxxxx> wrote:
>>>>>>>> Hi, Dmirty!
>>>>>>>>
>>>>>>>> On 04.06.2018 18:22, Dmitry Vyukov wrote:
>>>>>>>>> On Mon, Jun 4, 2018 at 5:03 PM, syzbot
>>>>>>>>> <syzbot+bf78a74f82c1cf19069e@xxxxxxxxxxxxxxxxxxxxxxxxx> wrote:
>>>>>>>>>> Hello,
>>>>>>>>>>
>>>>>>>>>> syzbot found the following crash on:
>>>>>>>>>>
>>>>>>>>>> HEAD commit:    bc2dbc5420e8 Merge branch 'akpm' (patches from Andrew)
>>>>>>>>>> git tree:       upstream
>>>>>>>>>> console output: https://syzkaller.appspot.com/x/log.txt?x=164e42b7800000
>>>>>>>>>> kernel config:  https://syzkaller.appspot.com/x/.config?x=982e2df1b9e60b02
>>>>>>>>>> dashboard link: https://syzkaller.appspot.com/bug?extid=bf78a74f82c1cf19069e
>>>>>>>>>> compiler:       gcc (GCC) 8.0.1 20180413 (experimental)
>>>>>>>>>>
>>>>>>>>>> Unfortunately, I don't have any reproducer for this crash yet.
>>>>>>>>>>
>>>>>>>>>> IMPORTANT: if you fix the bug, please add the following tag to the commit:
>>>>>>>>>> Reported-by: syzbot+bf78a74f82c1cf19069e@xxxxxxxxxxxxxxxxxxxxxxxxx
>>>>>>>>>
>>>>>>>>> Another hang on rtnl lock:
>>>>>>>>>
>>>>>>>>> #syz dup: INFO: task hung in netdev_run_todo
>>>>>>>>>
>>>>>>>>> May be related to "unregister_netdevice: waiting for DEV to become free":
>>>>>>>>> https://syzkaller.appspot.com/bug?id=1a97a5bd119fd97995f752819fd87840ab9479a9
>>>>>>>
>>>>>>> netdev_wait_allrefs does not hold rtnl lock during waiting, so it must
>>>>>>> be something different.
>>>>>>>
>>>>>>>
>>>>>>>>> Any other explanations for massive hangs on rtnl lock for minutes?
>>>>>>>>
>>>>>>>> To exclude the situation, when a task exists with rtnl_mutex held:
>>>>>>>>
>>>>>>>> would the pr_warn() from print_held_locks_bug() be included in the console output
>>>>>>>> if they appear?
>>>>>>>
>>>>>>> Yes, everything containing "WARNING:" is detected as bug.
>>>>>>
>>>>>> OK, then dead task not releasing the lock is excluded.
>>>>>>
>>>>>> One more assumption: someone corrupted memory around rtnl_mutex and it looks like locked.
>>>>>> (I track lockdep "(rtnl_mutex){+.+.}" prints in initial message as "nobody owns rtnl_mutex").
>>>>>> There may help a crash dump of the VM.
>>>>>
>>>>> I can't find any legend for these +'s and .'s, but {+.+.} is present
>>>>> in large amounts in just any task hung report for different mutexes,
>>>>> so I would not expect that it means corruption.
>>>>>
>>>>> Are dozens of known corruptions that syzkaller can trigger. But
>>>>> usually they are reliably caught by KASAN. If any of them would lead
>>>>> to silent memory corruption, we would got dozens of assorted crashes
>>>>> throughout the kernel. We've seen that at some points, but not
>>>>> recently. So I would assume that memory is not corrupted in all these
>>>>> cases:
>>>>> https://syzkaller.appspot.com/bug?id=2503c576cabb08d41812e732b390141f01a59545
>>>>
>>>> This BUG clarifies the {+.+.}:
>>>>
>>>> 4 locks held by kworker/0:145/381:
>>>>  #0:  ((wq_completion)"hwsim_wq"){+.+.}, at: [<000000003f9487f0>] work_static include/linux/workqueue.h:198 [inline]
>>>>  #0:  ((wq_completion)"hwsim_wq"){+.+.}, at: [<000000003f9487f0>] set_work_data kernel/workqueue.c:619 [inline]
>>>>  #0:  ((wq_completion)"hwsim_wq"){+.+.}, at: [<000000003f9487f0>] set_work_pool_and_clear_pending kernel/workqueue.c:646 [inline]
>>>>  #0:  ((wq_completion)"hwsim_wq"){+.+.}, at: [<000000003f9487f0>] process_one_work+0xb12/0x1bb0 kernel/workqueue.c:2084
>>>>  #1:  ((work_completion)(&data->destroy_work)){+.+.}, at: [<00000000bbdd2115>] process_one_work+0xb89/0x1bb0 kernel/workqueue.c:2088
>>>>  #2:  (rtnl_mutex){+.+.}, at: [<000000009c9d14f8>] rtnl_lock+0x17/0x20 net/core/rtnetlink.c:74
>>>>  #3:  (rcu_sched_state.exp_mutex){+.+.}, at: [<000000001ba1a807>] exp_funnel_lock kernel/rcu/tree_exp.h:272 [inline]
>>>>  #3:  (rcu_sched_state.exp_mutex){+.+.}, at: [<000000001ba1a807>] _synchronize_rcu_expedited.constprop.72+0x9fa/0xac0 kernel/rcu/tree_exp.h:596
>>>>
>>>> There we have rtnl_mutex locked and the {..} is like above. It's definitely locked
>>>> since there is one more lock after it.
>>>>
>>>> This BUG happen because of there are many rtnl_mutex waiters while owner
>>>> is synchronizing RCU. Rather clear for me in comparison to the topic's hung.
>>>
>>>
>>> You mean that it's not hanged, but rather needs more than 2 minutes to
>>> complete, right?
>>
>> Yeah, I think, this is possible. I've seen the situations like that.
>> Let synchronize_rcu_expedited() is executed for X seconds. Then,
>> it's need just 120/x calls of "this function under rtnl_mutex" to make
>> a soft lockup of someone else who wants the mutex too.
>>
>> Also, despite the CFS is fair scheduler, in case of the calls are
>> made from workqueue, every work will cause sleep. So, every work
>> will be executed in separate worker task. Every worker will haved its
>> own time slice. This increases the probability these tasks will
>> take cpu time before the task in the header of the hang.
> 
> 
> OK, let's stick with this theory for now. Looking at the crash frequencies here:
> https://syzkaller.appspot.com/bug?id=2503c576cabb08d41812e732b390141f01a59545
> I can actually believe that this is just flakes due to too slow execution.
> 
> I've noted that we need either reduce load and/or increase timeouts:
> https://github.com/google/syzkaller/issues/516#issuecomment-395685629

Hm, I'm not sure we should hide such the situations from syzbot,
because the load like this may occur in real life on real workload.
They may help us to understand whether rtnl_mutex already needs
a redesign came from this statistics. Also, these hungs may happen
in a place, which can be rewritten without rtnl_mutex, so we focus
attention on it.

> Let's keep duping new such reports onto "INFO: task hung in
> netdev_run_todo" so that they are all collected at a single location.
> 
> Thanks for help

Thanks,
Kirill