search

openzfs / zfs

OpenZFS on Linux and FreeBSD
https://openzfs.github.io/openzfs-docs
Other
10.47k stars 1.74k forks source link

Kernel panic on heavy ZFS usage? #1084

Closed jstam84 closed 11 years ago

jstam84 commented 11 years ago

Hi everyone,

I hope that one of you guys can shed some light on the following problem. Heavy loads on my zpool leads to a kernel panic. This problem can be reproduced with f.e. dd, tar or rsync. I'm using 3x1TB in a RAID-Z setup. The pool is used for personal data; root is on a RAID mirror.

I'm using Arch Linux and tried different (stock) kernels ranging from 3.0.51-1 (LTS) to the latest 3.6.6-1. I've combined the different kernel versions with the current git (master branch) and the official RC11 release and saw no difference in behaviour. I tried to use RC10 but it doesn't support preemptive kernels.

For zpool, besides RAID-Z, I've been able to reproduce this problem with a ZFS RAID mirror and a single ZFS partition. With every test I've run, the panic always occurs when memory is at ~50% usage:

1) KiB Mem: 8146968 total, 3510712 used, 4636256 free, 1780 buffers 2) KiB Mem: 7935800 total, 3504908 used, 4430892 free, 1531304 buffers 3) KiB Mem: 7935800 total, 3489640 used, 4446160 free, 135208 buffers

I'm unfamiliar with interpreting stack traces so I'm not sure whether this problem is isolated to ZFS although I'm unable to reproduce this without it. Since I'm not sure if this is related to issue 754, I'm posting this as a new issue (https://github.com/zfsonlinux/zfs/issues/754).

Smartctl (short & long) tests for my drives al come back OK.

Output for uname -a (atm): [jstam@moist ~]$ uname -a Linux moist.brempark.stam-online.nl 3.0.51-1-lts #1 SMP Mon Nov 5 11:54:31 CET 2012 x86_64 GNU/Linux

Example: when I run rsync (or tar or dd or...), RAM usage increases until segfault and /var/log/kernel.log gives the following output:

[ 634.794473] general protection fault: 0000 [#1] SMP [ 634.794510] CPU 2 [ 634.794521] Modules linked in: nf_conntrack_ipv6 nf_defrag_ipv6 xt_conntrack ip6t_LOG ip6t_REJECT ip6_queue ip6table_mangle ip6table_filter ip6_tables xt_CLASSIFY xt_TCPMSS xt_NFQUEUE xt_NFLOG nfnetlink_log ipt_LOG ipt_REJECT ipt_MASQUERADE ipt_REDIRECT xt_connmark xt_helper xt_mac xt_mark xt_limit xt_length xt_tcpudp nfnetlink_queue nfnetlink ip_queue nfsd nf_nat_ftp nf_conntrack_ftp xt_state iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack iptable_mangle iptable_filter ip_tables x_tables tda10023 tda10021 zfs(P) zunicode(P) zavl(P) zcommon(P) znvpair(P) spl zlib_deflate snd_hda_codec_realtek ir_lirc_codec i915 lirc_dev snd_hda_intel ir_sony_decoder ir_jvc_decoder snd_hda_codec ir_rc6_decoder ir_rc5_decoder snd_hwdep video ir_nec_decoder mantis snd_pcm i2c_algo_bit mantis_core snd_page_alloc drm_kms_helper snd_timer dvb_core drm snd usb_storage iTCO_wdt ftdi_sio ppdev rc_core iTCO_vendor_support uas soundcore parport_pc psmouse intel_agp usbserial e1000e r8169 i2c_i801 intel_gtt parport processor pcspkr serio_raw i2c_core button evdev joydev mii nfs nfs_acl auth_rpcgss fscache lockd sunrpc usbhid hid sd_mod ata_generic uhci_hcd pata_acpi pata_jmicron ahci ata_piix libahci libata scsi_mod ehci_hcd usbcore raid1 md_mod ext4 crc16 jbd2 mbcache [ 634.795281] [ 634.795291] Pid: 1255, comm: dd Tainted: P 3.0.51-1-lts #1 To Be Filled By O.E.M. To Be Filled By O.E.M./G41M-S3 [ 634.795348] RIP: 0010:[] [] spl_kmem_cache_alloc+0x2e5/0xfe0 [spl] [ 634.795401] RSP: 0018:ffff8801d6ac38b8 EFLAGS: 00010002 [ 634.795427] RAX: ffff880143b14180 RBX: ffff88020cd0a400 RCX: 0000000000000000 [ 634.795461] RDX: ffff880143b14000 RSI: 67ff880143b14020 RDI: ffff880143b142d0 [ 634.795494] RBP: ffff8801d6ac3998 R08: ffff880143b14010 R09: 2222222222222222 [ 634.795528] R10: ffff8801d6ac3958 R11: ffff8801d6ac3940 R12: ffff8802103c9000 [ 634.795562] R13: 000000000000007f R14: ffff88020cd0a710 R15: 0000000000000001 [ 634.795596] FS: 00007f031f831700(0000) GS:ffff88021fd00000(0000) knlGS:0000000000000000 [ 634.795635] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b [ 634.795662] CR2: 00007feba9f048a0 CR3: 00000001d4fa7000 CR4: 00000000000406e0 [ 634.795696] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 634.795729] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 [ 634.795763] Process dd (pid: 1255, threadinfo ffff8801d6ac2000, task ffff880211f307f0) [ 634.795800] Stack: [ 634.795812] ffff880143e3b0c0 ffff880211f307f0 2222222222222222 2222222222222222 [ 634.795855] 2222222222222222 2222222222222222 ffff8801d6ac3958 ffff8801d6ac3940 [ 634.795898] 0000000000000202 ffff88020cd0a718 ffff8801d6ac3958 ffff88020cd0a6f8 [ 634.795941] Call Trace: [ 634.795971] [] arc_buf_alloc+0x37/0xf0 [zfs] [ 634.796010] [] dbuf_read+0x2d1/0x8b0 [zfs] [ 634.796042] [] ? kmem_free_debug+0x4b/0x150 [spl] [ 634.796085] [] dmu_tx_check_ioerr+0xc3/0x140 [zfs] [ 634.796129] [] dmu_tx_count_write+0x21f/0x710 [zfs] [ 634.796162] [] ? __kmalloc+0x137/0x170 [ 634.797771] [] ? dbuf_rele_and_unlock+0x174/0x230 [zfs] [ 634.799385] [] ? kmem_alloc_debug+0x15e/0x500 [spl] [ 634.801014] [] dmu_tx_hold_write+0x41/0x60 [zfs] [ 634.802637] [] zfs_write+0x325/0xc60 [zfs] [ 634.803710] [] ? current_fs_time+0x16/0x60 [ 634.803710] [] zpl_write_common+0x52/0x80 [zfs] [ 634.803710] [] zpl_write+0x6b/0xa0 [zfs] [ 634.803710] [] vfs_write+0xa8/0x180 [ 634.803710] [] sys_write+0x4a/0xa0 [ 634.803710] [] system_call_fastpath+0x16/0x1b [ 634.803710] Code: 9a 00 00 00 41 83 ed 01 41 83 fd ff 0f 84 8c 00 00 00 41 83 c7 01 0f 84 82 00 00 00 48 8b 42 20 48 8b 70 08 48 8b 38 48 89 77 08 [ 634.803710] 89 3e 48 89 00 48 8b 35 4e 9c 47 e1 48 89 40 08 83 42 38 01 [ 634.803710] RIP [] spl_kmem_cache_alloc+0x2e5/0xfe0 [spl] [ 634.803710] RSP [ 634.803710] ---[ end trace a08b48412a042c72 ]---

Nov 10 17:50:33 moist kernel: [ 6037.419207] [] mmput+0x59/0x130 Nov 10 17:50:33 moist kernel: [ 6037.420549] [] exit_mm+0x108/0x130 Nov 10 17:50:33 moist kernel: [ 6037.421896] [] ? _raw_spin_unlock_irq+0x35/0x40 Nov 10 17:50:33 moist kernel: [ 6037.423250] [] do_exit+0x15f/0x940 Nov 10 17:50:33 moist kernel: [ 6037.424588] [] ? kmsg_dump+0xc4/0x110 Nov 10 17:50:33 moist kernel: [ 6037.425924] [] oops_end+0x9d/0xe0 Nov 10 17:50:33 moist kernel: [ 6037.427243] [] die+0x58/0x90 Nov 10 17:50:33 moist kernel: [ 6037.428560] [] do_general_protection+0x162/0x170 Nov 10 17:50:33 moist kernel: [ 6037.429868] [] general_protection+0x25/0x30 Nov 10 17:50:33 moist kernel: [ 6037.431191] [] ? spl_kmem_cache_alloc+0x4b7/0xe10 [spl] Nov 10 17:50:33 moist kernel: [ 6037.432512] [] ? spl_kmem_cache_alloc+0x204/0xe10 [spl] Nov 10 17:50:33 moist kernel: [ 6037.433823] [] ? zio_vdev_io_done+0x39/0x1a0 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.435126] [] zio_data_buf_alloc+0x23/0x30 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.436416] [] arc_get_data_buf.isra.19+0x102/0x440 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.437716] [] arc_buf_alloc+0xba/0xf0 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.438994] [] arc_read_nolock+0x22e/0x830 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.440291] [] arc_read+0x7f/0x170 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.441564] [] dsl_read+0x31/0x40 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.442840] [] dbuf_prefetch+0x16a/0x2b0 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.444111] [] dmu_zfetch_dofetch.isra.5+0xff/0x170 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.445386] [] dmu_zfetch+0x5d2/0x1090 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.446652] [] dbuf_read+0x4d7/0x8b0 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.447943] [] dmu_buf_hold_array_by_dnode+0x180/0x5b0 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.449216] [] dmu_buf_hold_array+0x66/0x90 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.450507] [] dmu_read_uio+0x41/0xe0 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.451788] [] zfs_read+0x17c/0x480 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.453073] [] zpl_read_common+0x52/0x80 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.454345] [] zpl_read+0x6b/0xa0 [zfs] Nov 10 17:50:33 moist kernel: [ 6037.455594] [] vfs_read+0xa5/0x180 Nov 10 17:50:33 moist kernel: [ 6037.456857] [] sys_read+0x4a/0xa0 Nov 10 17:50:33 moist kernel: [ 6037.458122] [] system_call_fastpath+0x16/0x1b

This is the output from top at the time of ssh dying: read from raid-z -> tar to BTRFS

top - 16:03:21 up 16 min, 3 users, load average: 0.48, 0.50, 0.40 Tasks: 261 total, 3 running, 258 sleeping, 0 stopped, 0 zombie %Cpu(s): 0.3 us, 10.4 sy, 0.0 ni, 88.8 id, 0.0 wa, 0.0 hi, 0.5 si, 0.0 st KiB Mem: 8146968 total, 3510712 used, 4636256 free, 1780 buffers KiB Swap: 4192188 total, 0 used, 4192188 free, 1685248 cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
12167 jstam 20 0 0 0 0 R 25.6 0.0 0:03.78 tar
319 root 20 0 63076 3484 2644 R 2.7 0.0 0:00.34 syslog-ng
449 root 20 0 0 0 0 S 2.7 0.0 0:00.55 flush-btrfs-2
9 root 20 0 0 0 0 S 2.3 0.0 0:00.22 kworker/1:0
321 hts 20 0 370m 12m 1852 S 1.7 0.2 0:09.79 tvheadend
11614 root 39 19 0 0 0 S 0.7 0.0 0:00.39 z_rd_int/1
11616 root 39 19 0 0 0 S 0.7 0.0 0:00.38 z_rd_int/3
114 root 20 0 0 0 0 S 0.3 0.0 0:00.04 kworker/3:2
160 root 20 0 0 0 0 S 0.3 0.0 0:00.18 btrfs-endio-wri
11613 root 39 19 0 0 0 S 0.3 0.0 0:00.37 z_rd_int/0
11615 root 39 19 0 0 0 S 0.3 0.0 0:00.38 z_rd_int/2
12166 jstam 20 0 13368 1848 1132 R 0.3 0.0 0:00.08 top
1 root 20 0 32644 3908 1968 S 0.0 0.0 0:00.35 systemd

Second run (notice ~same amount of used/free mem): write to zfs mirror; if=/dev/sda

top - 10:51:56 up 10 min, 3 users, load average: 2.00, 1.17, 0.63 Tasks: 284 total, 6 running, 278 sleeping, 0 stopped, 0 zombie %Cpu(s): 0.3 us, 26.1 sy, 0.0 ni, 71.9 id, 0.5 wa, 0.0 hi, 1.2 si, 0.0 st KiB Mem: 7935800 total, 3504908 used, 4430892 free, 1531304 buffers KiB Swap: 0 total, 0 used, 0 free, 61740 cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
125 root 20 0 0 0 0 S 3.3 0.0 0:40.77 md125_resync
618 hts 20 0 495m 11m 1812 S 3.3 0.1 0:20.97 tvheadend
108 root 20 0 0 0 0 S 0.7 0.0 0:07.08 md125_raid1
1075 jstam 20 0 78040 1932 1152 S 0.7 0.0 0:00.05 sshd
1076 jstam 20 0 15796 2404 1768 S 0.3 0.0 0:00.05 bash
1 root 20 0 32724 3768 1860 S 0.0 0.0 0:00.91 systemd

Thanks in advance,

Jan-Jaap Stam

jstam84 commented 11 years ago

Update: RAM strip faulty :S

This was a bit confusing. IIRC, ZFS claims as much RAM as possible and since I wasn't using as much without it, I couln't reproduce this problem.

I'm not closing this issue just yet; maybe a dev can confirm that these symptoms are normal with faulty RAM?

Thanks!

behlendorf commented 11 years ago

@jstam84 If you have faulty RAM almost anything is possible but the most likely behavior would be random crashing. If the corruption occurs in user space you may just see an application segfault and exit, when it happens to something running in the kernel your most likely to get a general protection fault.

When your content this was caused by faulty hardware please go ahead and close the issue.

jstam84 commented 11 years ago

@behlendorf Thanks for you comment. I understood as much, but I don't see these crashes being random. I'll close this issue for now as removing the faulty RAM seems to have solved my problems. If they surface again, I'll reopen this issue. Thanks for a marvelous job, and I'll keep following the progress of the project!