Skip to content
This repository has been archived by the owner on Feb 26, 2020. It is now read-only.

SPLError: 1620:0:(dbuf.c:101:dbuf_dest()) SPL PANIC #371

Closed
OmenWild opened this issue Jul 9, 2014 · 12 comments
Closed

SPLError: 1620:0:(dbuf.c:101:dbuf_dest()) SPL PANIC #371

OmenWild opened this issue Jul 9, 2014 · 12 comments
Labels
Milestone

Comments

@OmenWild
Copy link

OmenWild commented Jul 9, 2014

Twice since upgrading to 0.6.3 I have seen SPL PANIC's. They happen shortly after a cronjob kicks off a rsync of / (excluding the zpool of course) to a backup pool on ZFS. The latest was with kernel is 3.14.10, the previous would have been 3.14.9 .

ZFS/SPL version is the released packages:

SPL: Loaded module v0.6.3-295_ga9d5f15
ZFS: Loaded module v0.6.3-763_ge883253, ZFS pool version 5000, ZFS filesystem version 5

Both times the process to cause the PANIC was arc_adapt. The first time, the system kept working for around 36 hours then hung. This time I'm going to reboot it before it gets there.

First backtrace from July 5th:

Jul  8 01:00:22 balrog kernel: [96573.094190] VERIFY3(mutex_owner(&db->db_mtx) == ((void *)0)) failed (ffff8802cfe8e180 ==           (null))
Jul  8 01:00:22 balrog kernel: [96573.094196] SPLError: 1620:0:(dbuf.c:101:dbuf_dest()) SPL PANIC
Jul  8 01:00:22 balrog kernel: [96573.094197] SPL: Showing stack for process 1620
Jul  8 01:00:22 balrog kernel: [96573.094200] CPU: 1 PID: 1620 Comm: arc_adapt Tainted: P           O 3.14.11-ck1-1 #1
Jul  8 01:00:22 balrog kernel: [96573.094201] Hardware name: System manufacturer System Product Name/P8B WS, BIOS 2106 07/16/2012
Jul  8 01:00:22 balrog kernel: [96573.094202]  0000000000000000 ffff880406553d58 ffffffff83542c69 0000000000000000
Jul  8 01:00:22 balrog kernel: [96573.094204]  ffff880406553d68 ffffffffc00c7449 ffff880406553d88 ffffffffc00c86f3
Jul  8 01:00:22 balrog kernel: [96573.094206]  000000000000005e ffff8803bd598000 ffff880406553da0 ffffffffc01d1ecb
Jul  8 01:00:22 balrog kernel: [96573.094208] Call Trace:
Jul  8 01:00:22 balrog kernel: [96573.094214]  [<ffffffff83542c69>] dump_stack+0x4e/0x7a
Jul  8 01:00:22 balrog kernel: [96573.094226]  [<ffffffffc00c7449>] spl_debug_dumpstack+0x30/0x32 [spl]
Jul  8 01:00:22 balrog kernel: [96573.094230]  [<ffffffffc00c86f3>] spl_debug_bug+0x81/0xc6 [spl]
Jul  8 01:00:22 balrog kernel: [96573.094241]  [<ffffffffc01d1ecb>] dbuf_dest+0x40/0x5a [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094245]  [<ffffffffc00cb050>] spl_kmem_cache_free+0x83/0x2e5 [spl]
Jul  8 01:00:22 balrog kernel: [96573.094254]  [<ffffffffc01d32e9>] dbuf_destroy+0x119/0x12f [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094266]  [<ffffffffc0252bf0>] ? zpl_fill_super+0x12/0x12 [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094274]  [<ffffffffc01d3430>] dbuf_evict+0x1a/0x1d [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094282]  [<ffffffffc01d3a27>] dbuf_do_evict+0x42/0x5a [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094289]  [<ffffffffc01ca948>] arc_do_user_evicts+0x68/0xc9 [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094297]  [<ffffffffc01cc7e0>] arc_adapt_thread+0x22a/0x305 [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094304]  [<ffffffffc01cc5b6>] ? arc_adjust+0x113/0x113 [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094308]  [<ffffffffc00cdf0b>] thread_generic_wrapper+0x77/0x81 [spl]
Jul  8 01:00:22 balrog kernel: [96573.094311]  [<ffffffffc00cde94>] ? __thread_exit+0x95/0x95 [spl]
Jul  8 01:00:22 balrog kernel: [96573.094314]  [<ffffffff8308c657>] kthread+0xb7/0xbf
Jul  8 01:00:22 balrog kernel: [96573.094316]  [<ffffffff83090000>] ? srcu_notifier_chain_register+0x3e/0x53
Jul  8 01:00:22 balrog kernel: [96573.094318]  [<ffffffff8308c5a0>] ? __kthread_parkme+0x67/0x67
Jul  8 01:00:22 balrog kernel: [96573.094320]  [<ffffffff835500ac>] ret_from_fork+0x7c/0xb0
Jul  8 01:00:22 balrog kernel: [96573.094322]  [<ffffffff8308c5a0>] ? __kthread_parkme+0x67/0x67

Second backtrace from today (July 8th):

Jul  8 01:00:22 balrog kernel: [96573.094190] VERIFY3(mutex_owner(&db->db_mtx) == ((void *)0)) failed (ffff8802cfe8e180 ==
(null))                                                                                                                    
Jul  8 01:00:22 balrog kernel: [96573.094196] SPLError: 1620:0:(dbuf.c:101:dbuf_dest()) SPL PANIC
Jul  8 01:00:22 balrog kernel: [96573.094197] SPL: Showing stack for process 1620
Jul  8 01:00:22 balrog kernel: [96573.094200] CPU: 1 PID: 1620 Comm: arc_adapt Tainted: P           O 3.14.11-ck1-1 #1
Jul  8 01:00:22 balrog kernel: [96573.094201] Hardware name: System manufacturer System Product Name/P8B WS, BIOS 2106
07/16/2012                                                                                                             
Jul  8 01:00:22 balrog kernel: [96573.094202]  0000000000000000 ffff880406553d58 ffffffff83542c69 0000000000000000
Jul  8 01:00:22 balrog kernel: [96573.094204]  ffff880406553d68 ffffffffc00c7449 ffff880406553d88 ffffffffc00c86f3
Jul  8 01:00:22 balrog kernel: [96573.094206]  000000000000005e ffff8803bd598000 ffff880406553da0 ffffffffc01d1ecb
Jul  8 01:00:22 balrog kernel: [96573.094208] Call Trace:
Jul  8 01:00:22 balrog kernel: [96573.094214]  [<ffffffff83542c69>] dump_stack+0x4e/0x7a
Jul  8 01:00:22 balrog kernel: [96573.094226]  [<ffffffffc00c7449>] spl_debug_dumpstack+0x30/0x32 [spl]
Jul  8 01:00:22 balrog kernel: [96573.094230]  [<ffffffffc00c86f3>] spl_debug_bug+0x81/0xc6 [spl]
Jul  8 01:00:22 balrog kernel: [96573.094241]  [<ffffffffc01d1ecb>] dbuf_dest+0x40/0x5a [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094245]  [<ffffffffc00cb050>] spl_kmem_cache_free+0x83/0x2e5 [spl]
Jul  8 01:00:22 balrog kernel: [96573.094254]  [<ffffffffc01d32e9>] dbuf_destroy+0x119/0x12f [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094266]  [<ffffffffc0252bf0>] ? zpl_fill_super+0x12/0x12 [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094274]  [<ffffffffc01d3430>] dbuf_evict+0x1a/0x1d [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094282]  [<ffffffffc01d3a27>] dbuf_do_evict+0x42/0x5a [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094289]  [<ffffffffc01ca948>] arc_do_user_evicts+0x68/0xc9 [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094297]  [<ffffffffc01cc7e0>] arc_adapt_thread+0x22a/0x305 [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094304]  [<ffffffffc01cc5b6>] ? arc_adjust+0x113/0x113 [zfs]
Jul  8 01:00:22 balrog kernel: [96573.094308]  [<ffffffffc00cdf0b>] thread_generic_wrapper+0x77/0x81 [spl]
Jul  8 01:00:22 balrog kernel: [96573.094311]  [<ffffffffc00cde94>] ? __thread_exit+0x95/0x95 [spl]
Jul  8 01:00:22 balrog kernel: [96573.094314]  [<ffffffff8308c657>] kthread+0xb7/0xbf
Jul  8 01:00:22 balrog kernel: [96573.094316]  [<ffffffff83090000>] ? srcu_notifier_chain_register+0x3e/0x53
Jul  8 01:00:22 balrog kernel: [96573.094318]  [<ffffffff8308c5a0>] ? __kthread_parkme+0x67/0x67
Jul  8 01:00:22 balrog kernel: [96573.094320]  [<ffffffff835500ac>] ret_from_fork+0x7c/0xb0
Jul  8 01:00:22 balrog kernel: [96573.094322]  [<ffffffff8308c5a0>] ? __kthread_parkme+0x67/0x67

I am running with ECC RAM and the system seems otherwise stable, so it doesn't seem immediately like a hardware error.

My two small (~2TB each) zpools are otherwise healthy and working fine. One pool has ~80GB as l2arc.

1 > sudo zpool status -v 
  pool: bulk
 state: ONLINE
  scan: resilvered 2.91M in 0h0m with 0 errors on Sun Jul  6 22:14:34 2014
config:

    NAME                                          STATE     READ WRITE CKSUM
    bulk                                          ONLINE       0     0     0
      mirror-0                                    ONLINE       0     0     0
        ata-WDC_WD30EFRX-68AX9N0_WD-WMC1T1148946  ONLINE       0     0     0
        dm-name-zfs-bulk-2                        ONLINE       0     0     0

errors: No known data errors

  pool: tank
 state: ONLINE
  scan: scrub repaired 0 in 14h5m with 0 errors on Sun Jul  6 14:05:06 2014
config:

    NAME                                                STATE     READ WRITE CKSUM
    tank                                                ONLINE       0     0     0
      mirror-0                                          ONLINE       0     0     0
        ata-Hitachi_HDS723020BLA642_MN3220F32RR93E      ONLINE       0     0     0
        ata-Hitachi_HDS723020BLA642_MN5220F327K5BK      ONLINE       0     0     0
    cache
      ata-INTEL_SSDSC2MH250A2_LNEL130300QT250DGN-part2  ONLINE       0     0     0

errors: No known data errors

Module options are:

options zfs l2arc_write_boost=134217728 l2arc_write_max=67108864
options spl spl_kmem_cache_slab_limit=16384

Is there more data I can provide to help narrow this down?

@OmenWild
Copy link
Author

OmenWild commented Jul 9, 2014

I just got a similar panic on a different machine. This one does not have ECC RAM, but it also had options spl spl_kmem_cache_slab_limit=16384. This box is running 3.15.4 and:

SPL: Loaded module v0.6.3-295_ga9d5f15
ZFS: Loaded module v0.6.3-763_ge883253, ZFS pool version 5000, ZFS filesystem version 5

The setup on this box is slightly simpler. It has two small one disk pools, but no L2ARC.

The full dump:

[93077.914093] VERIFY3(mutex_owner(&db->db_mtx) == ((void *)0)) failed (ffff880601c56e40 ==           (null))
[93077.914108] SPLError: 1509:0:(dbuf.c:101:dbuf_dest()) SPL PANIC
[93077.914110] SPL: Showing stack for process 1509
[93077.914113] CPU: 5 PID: 1509 Comm: arc_adapt Tainted: P           O  3.15.4-ck1-1 #2
[93077.914115] Hardware name: Dell Inc. OptiPlex 9020/06X1TJ, BIOS A07 04/25/2014
[93077.914118]  0000000000000006 ffffffff834f9ca7 0000000000000000 ffffffffc0370595
[93077.914120]  000000000000005e ffff880110bb4fc0 ffffffffc0404a1e ffff88060bf22000
[93077.914122]  ffffffffc0372d13 ffff880110bb4fc0 ffffffffc04b2df8 00000000006030f1
[93077.914124] Call Trace:
[93077.914131]  [<ffffffff834f9ca7>] ? dump_stack+0x41/0x51
[93077.914132] BUG: unable to handle kernel 
[93077.914138]  [<ffffffffc0370595>] ? spl_debug_bug+0x78/0xbd [spl]
[93077.914144]  [<ffffffffc0404a1e>] ? dbuf_dest+0x37/0x50 [zfs]
[93077.914170]  [<ffffffffc0372d13>] ? spl_kmem_cache_free+0x7f/0x2ce [spl]
[93077.914175]  [<ffffffffc0375aa3>] ? __thread_exit+0x8c/0x8c [spl]
[93077.914179]  [<ffffffffc0405d17>] ? dbuf_destroy+0x10b/0x11e [zfs]
[93077.914190]  [<ffffffffc03ff411>] ? arc_adjust+0x109/0x109 [zfs]
[93077.914200]  [<ffffffffc04063d9>] ? dbuf_do_evict+0x39/0x50 [zfs]
[93077.914208]  [<ffffffffc03fd872>] ? arc_do_user_evicts+0x5e/0xbc [zfs]
[93077.914216]  [<ffffffffc03ff62a>] ? arc_adapt_thread+0x219/0x2f2 [zfs]
[93077.914226]  [<ffffffffc03ff411>] ? arc_adjust+0x109/0x109 [zfs]
[93077.914234]  [<ffffffffc0375aa3>] ? __thread_exit+0x8c/0x8c [spl]
[93077.914237]  [<ffffffffc0375b10>] ? thread_generic_wrapper+0x6d/0x75 [spl]
[93077.914240]  [<ffffffff8304e13a>] ? kthread+0xa7/0xaf
[93077.914244]  [<ffffffff8304e093>] ? __kthread_parkme+0x5b/0x5b
[93077.914246]  [<ffffffff835045fc>] ? ret_from_fork+0x7c/0xb0
[93077.914256]  [<ffffffff8304e093>] ? __kthread_parkme+0x5b/0x5b
[93077.914642] NULL pointer dereference at 0000000000000028
[93077.914664] IP: [<ffffffffc048013b>] zrl_add+0x0/0x4f [zfs]
[93077.914691] PGD 631f3067 PUD 9e6db067 PMD 0 
[93077.914705] Oops: 0000 [#1] SMP 
[93077.914716] Modules linked in: ufs qnx4 hfsplus hfs minix ntfs vfat msdos fat cpufreq_powersave cpufreq_conservative cpufreq_stats bnep rfcomm vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) binfmt_misc nfsd auth_rpcgss oid_registry nfs_acl nfs lockd fscache sunrpc sch_fq_codel ipt_REJECT xt_LOG xt_pkttype ipt_MASQUERADE iptable_nat nf_nat_ipv4 nf_nat xt_tcpudp nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack iptable_filter ip_tables x_tables fuse loop hid_microsoft hid_generic usbhid hid ecb btusb bluetooth uas usb_storage zfs(PO) zunicode(PO) zavl(PO) zcommon(PO) znvpair(PO) spl(O) snd_hda_codec_realtek snd_hda_codec_generic snd_hda_codec_hdmi snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep snd_pcm_oss snd_mixer_oss iTCO_wdt iTCO_vendor_support snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi x86_pkg_temp_thermal coretemp kvm_intel dcdbas snd_seq snd_seq_device snd_timer kvm psmouse mei_me lpc_ich i2c_i801 mei mfd_core serio_raw snd soundcore acpi_cpufreq evdev processor crct10dif_pclmul crct10dif_common crc32_pclmul ghash_clmulni_intel aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd sr_mod cdrom sd_mod thermal
[93077.914858] CPU: 3 PID: 3653 Comm: zfs-cache-sizes Tainted: P           O  3.15.4-ck1-1 #2
[93077.914859] Hardware name: Dell Inc. OptiPlex 9020/06X1TJ, BIOS A07 04/25/2014
[93077.914859] task: ffff880601c56e40 ti: ffff88012c400000 task.ti: ffff88012c400000
[93077.914860] RIP: 0010:[<ffffffffc048013b>]  [<ffffffffc048013b>] zrl_add+0x0/0x4f [zfs]
[93077.914873] RSP: 0018:ffff88012c403c50  EFLAGS: 00010213
[93077.914873] RAX: 0000000000000001 RBX: ffff880110bb4fc0 RCX: 0000000000000001
[93077.914874] RDX: ffff88049714cc00 RSI: ffff88012c403d48 RDI: 0000000000000000
[93077.914874] RBP: ffff880072d446a8 R08: ffffffffc04b30c0 R09: ffffffffffffffff
[93077.914875] R10: 0000000000000001 R11: 0000000000000001 R12: ffffc9002e08d000
[93077.914875] R13: ffff880110bb4fc0 R14: ffffc9002e08d000 R15: ffff880110bb5018
[93077.914876] FS:  00007f446d923700(0000) GS:ffff88062eac0000(0000) knlGS:0000000000000000
[93077.914876] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[93077.914877] CR2: 0000000000000028 CR3: 000000000b553000 CR4: 00000000001407e0
[93077.914877] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[93077.914877] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[93077.914878] Stack:
[93077.914878]  ffffffffc0404ea5 ffff880110bb4fc0 ffffffffc04082b9 0000000000001600
[93077.914879]  0000000000000001 00000000000000a8 0000000000004000 0000000000001600
[93077.914880]  000000130000002c 0000000000000000 0000000000000000 0000000000000000
[93077.914881] Call Trace:
[93077.914882]  [<ffffffffc0404ea5>] ? dbuf_is_metadata+0x1f/0x4c [zfs]
[93077.914891]  [<ffffffffc04082b9>] ? __dbuf_stats_hash_table_data+0x1e6/0x347 [zfs]
[93077.914901]  [<ffffffffc0408491>] ? dbuf_stats_hash_table_data+0x77/0xc7 [zfs]
[93077.914909]  [<ffffffffc037a7d8>] ? kstat_seq_show+0x3d/0x2b3 [spl]
[93077.914912]  [<ffffffff83111db2>] ? seq_read+0x255/0x323
[93077.914917]  [<ffffffff8313c06b>] ? proc_reg_read+0x55/0x6c
[93077.914922]  [<ffffffff830f8af9>] ? vfs_read+0x97/0xd9
[93077.914924]  [<ffffffff830f9271>] ? SyS_read+0x48/0x73
[93077.914925]  [<ffffffff835046a2>] ? system_call_fastpath+0x16/0x1b
[93077.914926] Code: 00 00 48 89 df e8 30 fa ff ff 48 8b 7c 24 08 89 44 24 04 e8 e2 f6 ff ff 8b 44 24 04 48 83 c4 10 5b c3 83 c8 ff f0 0f c1 47 28 c3 <8b> 57 28 83 fa ff 74 12 8d 4a 01 89 d0 f0 0f b1 4f 28 39 d0 74 
[93077.914937] RIP  [<ffffffffc048013b>] zrl_add+0x0/0x4f [zfs]
[93077.914948]  RSP <ffff88012c403c50>
[93077.914948] CR2: 0000000000000028
[93077.922902] ---[ end trace 444f3fbfd23b4bf9 ]---

@dweeezil
Copy link
Contributor

@OmenWild Could you please post the contents of /proc/spl/kstat/zfs/arcstats. I'm wondering how much arc is being eaten up to handle the 80GB of l2arc. It's entirely possible you've found a problem with the use of the Linux slab. Do you see this panic when not using options spl spl_kmem_cache_slab_limit=16384? It'll be interesting to hear how much RAM is in the system and what the arcstats look like.

@OmenWild
Copy link
Author

Unfortunately I have rebooted both boxes and disabled spl spl_kmem_cache_slab_limit=16384. If it does not come back in a week or so, then probably related.

Also keep in mind that the box providing the backtrace in the second post did not have any L2ARC at the time.

Current arcstats from the box providing the two back traces in the first post has 16GB RAM:

5 1 0x01 85 4080 1595520323 79533733266076
name                            type data
hits                            4    48493098
misses                          4    2085233
demand_data_hits                4    7468720
demand_data_misses              4    117254
demand_metadata_hits            4    39095942
demand_metadata_misses          4    881837
prefetch_data_hits              4    351297
prefetch_data_misses            4    847605
prefetch_metadata_hits          4    1577139
prefetch_metadata_misses        4    238537
mru_hits                        4    3275657
mru_ghost_hits                  4    567958
mfu_hits                        4    43557567
mfu_ghost_hits                  4    349012
deleted                         4    1280399
recycle_miss                    4    134291
mutex_miss                      4    2209
evict_skip                      4    41687509
evict_l2_cached                 4    32558443520
evict_l2_eligible               4    44752331264
evict_l2_ineligible             4    81561964032
hash_elements                   4    548691
hash_elements_max               4    555369
hash_collisions                 4    2013769
hash_chains                     4    161641
hash_chain_max                  4    11
p                               4    211663872
c                               4    3320719968
c_min                           4    4194304
c_max                           4    8349564928
size                            4    3320443616
hdr_size                        4    51527616
data_size                       4    1372630528
meta_size                       4    794026496
other_size                      4    959272680
anon_size                       4    165888
anon_evict_data                 4    0
anon_evict_metadata             4    0
mru_size                        4    376157184
mru_evict_data                  4    134328320
mru_evict_metadata              4    1551360
mru_ghost_size                  4    2932074496
mru_ghost_evict_data            4    2491524608
mru_ghost_evict_metadata        4    440549888
mfu_size                        4    1790333952
mfu_evict_data                  4    1238302208
mfu_evict_metadata              4    251627008
mfu_ghost_size                  4    242623488
mfu_ghost_evict_data            4    227712512
mfu_ghost_evict_metadata        4    14910976
l2_hits                         4    591060
l2_misses                       4    1493959
l2_feeds                        4    76664
l2_rw_clash                     4    4
l2_read_bytes                   4    2432932352
l2_write_bytes                  4    13241740800
l2_writes_sent                  4    14338
l2_writes_done                  4    14338
l2_writes_error                 4    0
l2_writes_hdr_miss              4    16
l2_evict_lock_retry             4    0
l2_evict_reading                4    0
l2_free_on_write                4    699
l2_abort_lowmem                 4    2913
l2_cksum_bad                    4    0
l2_io_error                     4    0
l2_size                         4    20434082304
l2_asize                        4    12287581184
l2_hdr_size                     4    142986296
l2_compress_successes           4    358026
l2_compress_zeros               4    0
l2_compress_failures            4    56331
memory_throttle_count           4    0
duplicate_buffers               4    0
duplicate_buffers_size          4    0
duplicate_reads                 4    0
memory_direct_count             4    79586
memory_indirect_count           4    239131
arc_no_grow                     4    0
arc_tempreserve                 4    0
arc_loaned_bytes                4    0
arc_prune                       4    0
arc_meta_used                   4    1947813088
arc_meta_limit                  4    6262173696
arc_meta_max                    4    5590213368

@OmenWild
Copy link
Author

Since I disabled spl spl_kmem_cache_slab_limit=16384 a week ago this issue has not reoccurred. If anyone has any ideas for debugging I could change one of the boxes back and wait for it to happen again.

@behlendorf behlendorf added this to the 0.6.4 milestone Jul 18, 2014
@behlendorf behlendorf added the Bug label Jul 18, 2014
@behlendorf
Copy link
Contributor

I have a theory which explains this. One which will probably interest @ryao.

Normally when an object is free'd back to the spl slab the registered destructors for that object are not run until the slab itself is freed. However, when using the Linux slab we must run the registered destructors immediately in the context on spl_kmem_cache_free.

According to the VERIFY() in the crash the act of calling dbuf_dest() immediately has exposed a use-after-free race in the dbuf code. There is clearly still some process holding the db->db_mtx which is about to be destroyed.

This has the potential to cause all sorts of otherwise mysterious problems which are exceptionally hard to debug. We definitely need to run down this race and get it resolved. This is also a really good argument for immediately calling the destructor as @ryao has proposed... although it's also now clear we can't do that until we find and fix this race...

@ryao
Copy link
Contributor

ryao commented Jul 18, 2014

@OmenWild Are you using xattr=sa?

@behlendorf A double free make sense here. We should try leveraging address sanitizer to help us track it down:

https://code.google.com/p/address-sanitizer/wiki/AddressSanitizerForKernel

@OmenWild
Copy link
Author

No xattr=sa on either box. One has xattr's completely disabled on all pools/file-systems, the other is the default: xattr on .

@behlendorf
Copy link
Contributor

@ryao I suspect we can get quite far with this just through code inspection now that we have a couple stacks.

@ryao
Copy link
Contributor

ryao commented Jul 19, 2014

@ryao I suspect we can get quite far with this just through code inspection now that we have a couple stacks.

Visual inspection is very tedious and will only result in one bug fix. If there happen to be multiple bugs in this class and we could use a tool like address sanitizer to catch this one, we would have a chance to catch more than one.

A cursory review of the code failed to reveal the double free. I am splitting the time I spend on this between code inspection and running address sanitizer on ztest. I have caught a few bugs via the latter method, but nothing that constitutes a serious issue like a double free.

@ryao ryao mentioned this issue Jul 20, 2014
@behlendorf
Copy link
Contributor

@ryao Sure, address sanitizers are a good thing. I was just suggesting we probably don't need one to find this issue. We could also just use the SLAB_RED_ZONE and SLAB_POISON slab flags and a debug kernel to verify this.

A cursory review of the code failed to reveal the double free.

Note that this doesn't need to be a double free, a use-after-free would cause the same issue.

@ryao
Copy link
Contributor

ryao commented Oct 2, 2014

@behlendorf
Copy link
Contributor

Closing, this hasn't been reproduced to my knowledge in years and has very likely been fixed. We can reopen in the ZFS track if someone is able to reproduce this.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

No branches or pull requests

4 participants