Re: btrfs panic problem

["sunny.s.zhang" <sunny.s.zhang@oracle.com>]

在 2018年09月19日 08:05, Qu Wenruo 写道:
>
> On 2018/9/18 上午8:28, sunny.s.zhang wrote:
>> Hi All,
>>
>> My OS(4.1.12) panic in kmem_cache_alloc, which is called by
>> btrfs_get_or_create_delayed_node.
> Any reproducer?
>
> Anyway we need a reproducer as a testcase.

I have had a try, but could not  reproduce yet.

Any advice to reproduce it?

>
> The code looks
>
>> I found that the freelist of the slub is wrong.
>>
>> crash> struct kmem_cache_cpu ffff887e7d7a24b0
>>
>> struct kmem_cache_cpu {
>>    freelist = 0x2026,   <<< the value is id of one inode
>>    tid = 29567861,
>>    page = 0xffffea0132168d00,
>>    partial = 0x0
>> }
>>
>> And, I found there are two different btrfs inodes pointing delayed_node.
>> It means that the same slub is used twice.
>>
>> I think this slub is freed twice, and then the next pointer of this slub
>> point itself. So we get the same slub twice.
>>
>> When use this slub again, that break the freelist.
>>
>> Folloing code will make the delayed node being freed twice. But I don't
>> found what is the process.
>>
>> Process A (btrfs_evict_inode) Process B
>>
>> call btrfs_remove_delayed_node call  btrfs_get_delayed_node
>>
>> node = ACCESS_ONCE(btrfs_inode->delayed_node);
>>
>> BTRFS_I(inode)->delayed_node = NULL;
>> btrfs_release_delayed_node(delayed_node);
>>
>> if (node) {
>> atomic_inc(&node->refs);
>> return node;
>> }
>>
>> ......
>>
>> btrfs_release_delayed_node(delayed_node);
>>
>>
>> 1313 void btrfs_remove_delayed_node(struct inode *inode)
>> 1314 {
>> 1315         struct btrfs_delayed_node *delayed_node;
>> 1316
>> 1317         delayed_node = ACCESS_ONCE(BTRFS_I(inode)->delayed_node);
>> 1318         if (!delayed_node)
>> 1319                 return;
>> 1320
>> 1321         BTRFS_I(inode)->delayed_node = NULL;
>> 1322         btrfs_release_delayed_node(delayed_node);
>> 1323 }
>>
>>
>>    87 static struct btrfs_delayed_node *btrfs_get_delayed_node(struct
>> inode *inode)
>>    88 {
>>    89         struct btrfs_inode *btrfs_inode = BTRFS_I(inode);
>>    90         struct btrfs_root *root = btrfs_inode->root;
>>    91         u64 ino = btrfs_ino(inode);
>>    92         struct btrfs_delayed_node *node;
>>    93
>>    94         node = ACCESS_ONCE(btrfs_inode->delayed_node);
>>    95         if (node) {
>>    96                 atomic_inc(&node->refs);
>>    97                 return node;
>>    98         }
>>
> The analyse looks valid.
> Can be fixed by adding a spinlock.
>
> Just wondering why we didn't hit it.

It just appeared once in our production environment.

Thanks,
Sunny
>
> Thanks,
> Qu
>
>> Thanks,
>>
>> Sunny
>>
>>
>> PS:
>>
>> ------------------------------------------------
>>
>> panic informations
>>
>> PID: 73638  TASK: ffff887deb586200  CPU: 38  COMMAND: "dockerd"
>>   #0 [ffff88130404f940] machine_kexec at ffffffff8105ec10
>>   #1 [ffff88130404f9b0] crash_kexec at ffffffff811145b8
>>   #2 [ffff88130404fa80] oops_end at ffffffff8101a868
>>   #3 [ffff88130404fab0] no_context at ffffffff8106ea91
>>   #4 [ffff88130404fb00] __bad_area_nosemaphore at ffffffff8106ec8d
>>   #5 [ffff88130404fb50] bad_area_nosemaphore at ffffffff8106eda3
>>   #6 [ffff88130404fb60] __do_page_fault at ffffffff8106f328
>>   #7 [ffff88130404fbd0] do_page_fault at ffffffff8106f637
>>   #8 [ffff88130404fc10] page_fault at ffffffff816f6308
>>      [exception RIP: kmem_cache_alloc+121]
>>      RIP: ffffffff811ef019  RSP: ffff88130404fcc8  RFLAGS: 00010286
>>      RAX: 0000000000000000  RBX: 0000000000000000  RCX: 0000000001c32b76
>>      RDX: 0000000001c32b75  RSI: 0000000000000000  RDI: 00000000000224b0
>>      RBP: ffff88130404fd08   R8: ffff887e7d7a24b0   R9: 0000000000000000
>>      R10: ffff8802668b6618  R11: 0000000000000002  R12: ffff887e3e230a00
>>      R13: 0000000000002026  R14: ffff887e3e230a00  R15: ffffffffa01abf49
>>      ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
>>   #9 [ffff88130404fd10] btrfs_get_or_create_delayed_node at
>> ffffffffa01abf49 [btrfs]
>> #10 [ffff88130404fd60] btrfs_delayed_update_inode at ffffffffa01aea12
>> [btrfs]
>> #11 [ffff88130404fdb0] btrfs_update_inode at ffffffffa015b199 [btrfs]
>> #12 [ffff88130404fdf0] btrfs_dirty_inode at ffffffffa015cd11 [btrfs]
>> #13 [ffff88130404fe20] btrfs_update_time at ffffffffa015fa25 [btrfs]
>> #14 [ffff88130404fe50] touch_atime at ffffffff812286d3
>> #15 [ffff88130404fe90] iterate_dir at ffffffff81221929
>> #16 [ffff88130404fee0] sys_getdents64 at ffffffff81221a19
>> #17 [ffff88130404ff50] system_call_fastpath at ffffffff816f2594
>>      RIP: 00000000006b68e4  RSP: 000000c866259080  RFLAGS: 00000246
>>      RAX: ffffffffffffffda  RBX: 000000c828dbbe00  RCX: 00000000006b68e4
>>      RDX: 0000000000001000  RSI: 000000c83da14000  RDI: 0000000000000011
>>      RBP: 0000000000000000   R8: 0000000000000000   R9: 0000000000000000
>>      R10: 0000000000000000  R11: 0000000000000246  R12: 00000000000000c7
>>      R13: 0000000002174e74  R14: 0000000005555555  R15: 0000000000000038
>>      ORIG_RAX: 00000000000000d9  CS: 0033  SS: 002b
>>
>>
>> We also find the list double add informations, including n_list and p_list:
>>
>> [8642921.110568] ------------[ cut here ]------------
>> [8642921.167929] WARNING: CPU: 38 PID: 73638 at lib/list_debug.c:33
>> __list_add+0xbe/0xd0()
>> [8642921.263780] list_add corruption. prev->next should be next
>> (ffff887e40fa5368), but was ff:ff884c85a36288. (prev=ffff884c85a36288).
>> [8642921.405490] Modules linked in: ipt_MASQUERADE
>> nf_nat_masquerade_ipv4 xt_conntrack iptable_filter arc4 ecb ppp_mppe
>> ppp_async crc_ccitt ppp_generic slhc nfsv3 nfs_acl rpcsec_gss_krb5
>> auth_rpcgss nfsv4 nfs fscache lockd sunrpc grace veth xt_nat xt_addrtype
>> br_netfilter bridge tcp_diag inet_diag oracleacfs(POE) oracleadvm(POE)
>> oracleoks(POE) oracleasm autofs4 dm_queue_length cpufreq_powersave
>> be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i iw_cxgb4 cxgb4 cxgb3i
>> libcxgbi iw_cxgb3 cxgb3 ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core
>> ib_addr iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi 8021q mrp
>> garp stp llc bonding iptable_nat nf_nat_ipv4 nf_nat ipt_REJECT
>> nf_reject_ipv4 xt_pkttype nf_conntrack_ipv4 nf_defrag_ipv4 ip_tables
>> ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 xt_state
>> [8642922.259780]  nf_conntrack ip6table_filter ip6_tables ipv6
>> dm_multipath sg iTCO_wdt iTCO_vendor_support ipmi_devintf ipmi_si
>> ipmi_msghandler intel_powerclamp coretemp kvm_intel kvm pcspkr ixgbe dca
>> ptp pps_core vxlan udp_tunnel ip6_udp_tunnel mdio sb_edac edac_core
>> i2c_i801 i2c_core lpc_ich mfd_core shpchp ext4 jbd2 mbcache2 btrfs
>> raid6_pq xor sd_mod megaraid_sas ghash_clmulni_intel crc32_pclmul
>> crc32c_intel aesni_intel ablk_helper cryptd lrw gf128mul glue_helper
>> aes_x86_64 ahci libahci mxm_wmi wmi dm_mirror dm_region_hash dm_log
>> dm_mod [last unloaded: xt_conntrack]
>> [8642922.850285] CPU: 38 PID: 73638 Comm: dockerd Tainted: P
>> OE   4.1.12-112.14.13.el6uek.x86_64 #2
>> [8642922.965881] Hardware name: Oracle Corporation ORACLE SERVER
>> X6-2/ASM,MOTHERBOARD,1U, BIOS 38040100 06/06/2016
>> [8642923.086670]  0000000000000000 ffff88130404fc28 ffffffff816ec91e
>> ffff88130404fc78
>> [8642923.177730]  0000000000000021 ffff88130404fc68 ffffffff81088925
>> 00ff88130404fc98
>> [8642923.268793]  ffff884c85a36288 ffff887e40fa5368 ffff884c85a36288
>> 0000000000000000
>> [8642923.359851] Call Trace:
>> [8642923.391194]  [<ffffffff816ec91e>] dump_stack+0x63/0x85
>> [8642923.454780]  [<ffffffff81088925>] warn_slowpath_common+0x95/0xe0
>> [8642923.528769]  [<ffffffff81088a26>] warn_slowpath_fmt+0x46/0x50
>> [8642923.599635]  [<ffffffff81343f3e>] __list_add+0xbe/0xd0
>> [8642923.663333]  [<ffffffffa01abb92>]
>> btrfs_queue_delayed_node+0xb2/0xe0 [btrfs]
>> [8642923.749898]  [<ffffffffa01abc66>]
>> __btrfs_release_delayed_node+0xa6/0x160 [btrfs]
>> [8642923.841661]  [<ffffffffa01aea5e>]
>> btrfs_delayed_update_inode+0x7e/0x100 [btrfs]
>> [8642923.931336]  [<ffffffffa015b199>] btrfs_update_inode+0xa9/0x130
>> [btrfs]
>> [8642924.012686]  [<ffffffffa015cd11>] btrfs_dirty_inode+0x71/0xe0 [btrfs]
>> [8642924.091954]  [<ffffffffa015fa25>] btrfs_update_time+0x65/0xc0 [btrfs]
>> [8642924.171145]  [<ffffffff812286d3>] touch_atime+0x123/0x170
>> [8642924.237849]  [<ffffffff81221929>] iterate_dir+0xf9/0x140
>> [8642924.303512]  [<ffffffff81221a19>] SyS_getdents64+0xa9/0x100
>> [8642924.372296]  [<ffffffff81221720>] ? fillonedir+0xe0/0xe0
>> [8642924.437963]  [<ffffffff816f2594>] system_call_fastpath+0x12/0xce
>> [8642924.512201] ---[ end trace 6782707b09f9f873 ]---
>> [8642924.569677] ------------[ cut here ]------------
>> [8642924.627055] WARNING: CPU: 38 PID: 73638 at lib/list_debug.c:36
>> __list_add+0x9c/0xd0()
>> [8642924.722925] list_add double add: new=ffff884c85a36288,
>> prev=ffff884c85a36288, next=ffff887e40fa5368.
>> [8642924.834373] Modules linked in: ipt_MASQUERADE
>> nf_nat_masquerade_ipv4 xt_conntrack iptable_filter arc4 ecb ppp_mppe
>> ppp_async crc_ccitt ppp_generic slhc nfsv3 nfs_acl rpcsec_gss_krb5
>> auth_rpcgss nfsv4 nfs fscache lockd sunrpc grace veth xt_nat xt_addrtype
>> br_netfilter bridge tcp_diag inet_diag oracleacfs(POE) oracleadvm(POE)
>> oracleoks(POE) oracleasm autofs4 dm_queue_length cpufreq_powersave
>> be2iscsi iscsi_boot_sysfs bnx2i cnic uio cxgb4i iw_cxgb4 cxgb4 cxgb3i
>> libcxgbi iw_cxgb3 cxgb3 ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core
>> ib_addr iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi 8021q mrp
>> garp stp llc bonding iptable_nat nf_nat_ipv4 nf_nat ipt_REJECT
>> nf_reject_ipv4 xt_pkttype nf_conntrack_ipv4 nf_defrag_ipv4 ip_tables
>> ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 xt_state
>> [8642925.688498]  nf_conntrack ip6table_filter ip6_tables ipv6
>> dm_multipath sg iTCO_wdt iTCO_vendor_support ipmi_devintf ipmi_si
>> ipmi_msghandler intel_powerclamp coretemp kvm_intel kvm pcspkr ixgbe dca
>> ptp pps_core vxlan udp_tunnel ip6_udp_tunnel mdio sb_edac edac_core
>> i2c_i801 i2c_core lpc_ich mfd_core shpchp ext4 jbd2 mbcache2 btrfs
>> raid6_pq xor sd_mod megaraid_sas ghash_clmulni_intel crc32_pclmul
>> crc32c_intel aesni_intel ablk_helper cryptd lrw gf128mul glue_helper
>> aes_x86_64 ahci libahci mxm_wmi wmi dm_mirror dm_region_hash dm_log
>> dm_mod [last unloaded: xt_conntrack]
>> [8642926.279029] CPU: 38 PID: 73638 Comm: dockerd Tainted: P        W
>> OE   4.1.12-112.14.13.el6uek.x86_64 #2
>> [8642926.394626] Hardware name: Oracle Corporation ORACLE SERVER
>> X6-2/ASM,MOTHERBOARD,1U, BIOS 38040100 06/06/2016
>> [8642926.515421]  0000000000000000 ffff88130404fc28 ffffffff816ec91e
>> ffff88130404fc78
>> [8642926.606485]  0000000000000024 ffff88130404fc68 ffffffff81088925
>> 00ff88130404fc98
>> [8642926.697544]  ffff884c85a36288 ffff887e40fa5368 ffff884c85a36288
>> 0000000000000000
>> [8642926.788605] Call Trace:
>> [8642926.819945]  [<ffffffff816ec91e>] dump_stack+0x63/0x85
>> [8642926.883535]  [<ffffffff81088925>] warn_slowpath_common+0x95/0xe0
>> [8642926.957529]  [<ffffffff81088a26>] warn_slowpath_fmt+0x46/0x50
>> [8642927.028400]  [<ffffffff81343f1c>] __list_add+0x9c/0xd0
>> [8642927.092116]  [<ffffffffa01abb92>]
>> btrfs_queue_delayed_node+0xb2/0xe0 [btrfs]
>> [8642927.178669]  [<ffffffffa01abc66>]
>> __btrfs_release_delayed_node+0xa6/0x160 [btrfs]
>> [8642927.270440]  [<ffffffffa01aea5e>]
>> btrfs_delayed_update_inode+0x7e/0x100 [btrfs]
>> [8642927.360112]  [<ffffffffa015b199>] btrfs_update_inode+0xa9/0x130
>> [btrfs]
>> [8642927.441447]  [<ffffffffa015cd11>] btrfs_dirty_inode+0x71/0xe0 [btrfs]
>> [8642927.520716]  [<ffffffffa015fa25>] btrfs_update_time+0x65/0xc0 [btrfs]
>> [8642927.599910]  [<ffffffff812286d3>] touch_atime+0x123/0x170
>> [8642927.666615]  [<ffffffff81221929>] iterate_dir+0xf9/0x140
>> [8642927.732284]  [<ffffffff81221a19>] SyS_getdents64+0xa9/0x100
>> [8642927.801072]  [<ffffffff81221720>] ? fillonedir+0xe0/0xe0
>> [8642927.866741]  [<ffffffff816f2594>] system_call_fastpath+0x12/0xce
>> [8642927.940843] ---[ end trace 6782707b09f9f874 ]---
>> [8642927.998378] ------------[ cut here ]------------
>>
>>
>>
>>