Re: WARNING: at include/net/sock.h:417 udp_lib_unhash

[Eric Dumazet <eric.dumazet@gmail.com>]

Eric Dumazet a écrit :
> Emil S Tantilov a écrit :
>> On Wed, Jul 1, 2009 at 11:10 PM, Eric Dumazet<eric.dumazet@gmail.com> wrote:
>>> Tantilov, Emil S a écrit :
>>>> I see the following trace during netperf stress mixed UDP/TCP IPv4/6 traffic. This is on recent pulls from net-2.6 and net-next.
>>>>
>>>> [45197.989163] ------------[ cut here ]------------
>>>> [45197.994309] WARNING: at include/net/sock.h:417 udp_lib_unhash+0x81/0xab()
>>>> [45197.994311] Hardware name: X7DA8
>>>> [45197.994314] Modules linked in: e1000 [last unloaded: e1000]
>>>> [45197.994326] Pid: 7110, comm: netserver Tainted: G        W  2.6.31-rc1-net-next-e1000-06250902 #8
>>>> [45197.994331] Call Trace:
>>>> [45197.994336]  [<ffffffff8135e0dc>] ? udp_lib_unhash+0x81/0xab
>>>> [45197.994344]  [<ffffffff8103cac9>] warn_slowpath_common+0x77/0x8f
>>>> [45197.994349]  [<ffffffff8103caf0>] warn_slowpath_null+0xf/0x11
>>>> [45197.994352]  [<ffffffff8135e0dc>] udp_lib_unhash+0x81/0xab
>>>> [45197.994357]  [<ffffffff81301acb>] sk_common_release+0x2f/0xb4
>>>> [45197.994364]  [<ffffffff813a0256>] udp_lib_close+0x9/0xb
>>>> [45197.994369]  [<ffffffff81364259>] inet_release+0x58/0x5f
>>>> [45197.994374]  [<ffffffff8138c8bd>] inet6_release+0x30/0x35
>>>> [45197.994383]  [<ffffffff812ff273>] sock_release+0x1a/0x6c
>>>> [45197.994386]  [<ffffffff812ff763>] sock_close+0x22/0x26
>>>> [45197.994392]  [<ffffffff810c69a0>] __fput+0xf0/0x18c
>>>> [45197.994395]  [<ffffffff810c6d00>] fput+0x15/0x19
>>>> [45197.994399]  [<ffffffff810c3c3e>] filp_close+0x5c/0x67
>>>> [45197.994404]  [<ffffffff810c3cc4>] sys_close+0x7b/0xb6
>>>> [45197.994412]  [<ffffffff8100baeb>] system_call_fastpath+0x16/0x1b
>>>> [45197.994418] ---[ end trace 5acab6fc0afdaaa3 ]---
>>>>
>>>> Emil--
>>> Thanks for this report Emil.
>>>
>>> I could not find a recent change in this area in last kernels.
>>> If struct sk is hashed (sk_hashed() true), then sk_refcnt was incremented
>>> in sk_nulls_add_node_rcu(), thus its value should be >= 2.
>>>
>>> Maybe we have a missing memory barrier somewhere or a list corruption.
>>>
>>> 1) Could you try CONFIG_DEBUG_LIST=y ?
>> I am running a test with this option now. Sorry for the delayed
>> response, I was out last week.
>>
>>> 2) Could you give model of cpu, since it reminds me the ongoing discussion raised by Jiri Olsa.
>> processor	: 0
>> vendor_id	: GenuineIntel
>> cpu family	: 6
>> model		: 23
>> model name	: Intel(R) Xeon(R) CPU           E5450  @ 3.00GHz
>> stepping	: 6
>> cpu MHz		: 2999.790
>> cache size	: 6144 KB
>> physical id	: 0
>> siblings	: 4
>> core id		: 0
>> cpu cores	: 4
>> apicid		: 0
>> initial apicid	: 0
>> fpu		: yes
>> fpu_exception	: yes
>> cpuid level	: 10
>> wp		: yes
>> flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov
>> pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx
>> lm constant_tsc arch_perfmon pebs bts rep_good pni dtes64 monitor
>> ds_cpl vmx est tm2 ssse3 cx16 xtpr pdcm dca sse4_1 lahf_lm tpr_shadow
>> vnmi flexpriority
>> bogomips	: 5999.58
>> clflush size	: 64
>>
>> 2 quad core Xeons, I only included the output from the first to reduce clutter.
>>
>>> CPU1 does an atomic_inc(&sk->sk_refcnt)  : refcnt changes from 1 to 2
>>> then CPU2 does an atomic_read(&sk->sk_refcnt) and reads 1 instead of 2
>>>
>>> David, maybe this test is not safe and if we really want to do a check
>>> we need to use a stronger atomic function.
>>>
>>> If you can reproduce this problem easily could you try following patch ?
>> It varies from few minutes to hours, but it does reproduce
>> consistently in my tests so far. I will try your patch once I manage
>> to get a trace with CONFIG_DEBUG_LIST
>>
> 
> 
> Eventually, could you also use following debug/quick&dirty patch ?
> 
> 
> diff --git a/include/net/sock.h b/include/net/sock.h
> index 352f06b..548f822 100644
> --- a/include/net/sock.h
> +++ b/include/net/sock.h
> @@ -376,6 +376,7 @@ static __inline__ int __sk_del_node_init(struct sock *sk)
>  
>  static inline void sock_hold(struct sock *sk)
>  {
> +	WARN_ON(atomic_read(&sk->sk_refcnt) == 0);
>  	atomic_inc(&sk->sk_refcnt);
>  }
>  
> @@ -385,6 +386,7 @@ static inline void sock_hold(struct sock *sk)
>  static inline void __sock_put(struct sock *sk)
>  {
>  	atomic_dec(&sk->sk_refcnt);
> +	WARN_ON(atomic_read(&sk->sk_refcnt) == 0);
>  }
>  
>  static __inline__ int sk_del_node_init(struct sock *sk)
> 

Hold on, I found the problem and will submit a patch (after testing it) in following hours

Thanks