search

openzfs / zfs

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

GPF in ZFS during light load #7940

Closed johnkeates closed 3 years ago

johnkeates commented 6 years ago

System information

Type Version/Name
Distribution Name Debian
Distribution Version 9.5
Linux Kernel 4.17.0-0.bpo.3-amd64
Architecture AMD64
ZFS Version 0.7.9-3~bpo9+1
SPL Version 0.7.9-3~bpo9+1

Describe the problem you're observing

Performance drops then hangs

Describe how to reproduce the problem

Happens once every few weeks

Include any warning/errors/backtraces from the system logs

[189265.997429] general protection fault: 0000 [#1] SMP NOPTI
[189265.999280] Modules linked in: ipmi_si xt_physdev br_netfilter bridge stp llc iptable_filter tun mptctl mptbase openvswitch nsh nf_conntrack_ipv6 nf_nat_ipv6 nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_defrag_ipv6 nf_nat nf_conntrack libcrc32c dell_rbu ext4 crc16 mbcache jbd2 crc32c_generic fscrypto ecb crypto_simd cryptd glue_helper aes_x86_64 iTCO_wdt iTCO_vendor_support intel_powerclamp dcdbas serio_raw pcspkr evdev joydev mgag200 ttm drm_kms_helper drm lpc_ich i2c_algo_bit sg ipmi_devintf ioatdma i7core_edac dca wmi acpi_power_meter ipmi_msghandler button shpchp xen_pciback xen_netback xen_blkback xen_gntalloc xen_gntdev xenfs xen_evtchn xen_privcmd ip_tables x_tables autofs4 zfs(PO) zunicode(PO) zavl(PO) icp(PO) zcommon(PO) znvpair(PO) spl(O) uas usb_storage hid_generic usbhid hid sd_mod
[189266.013980]  crc32c_intel psmouse uhci_hcd ehci_pci ehci_hcd ahci libahci usbcore libata usb_common mpt3sas raid_class scsi_transport_sas scsi_mod bnx2 [last unloaded: ipmi_si]
[189266.018295] CPU: 0 PID: 31717 Comm: z_rd_int_0 Tainted: P           O      4.17.0-0.bpo.3-amd64 #1 Debian 4.17.17-1~bpo9+1
[189266.020617] Hardware name: Dell Inc. PowerEdge R710/07THW3, BIOS 6.4.0 07/23/2013
[189266.022767] RIP: e030:avl_walk+0x2f/0x60 [zavl]
[189266.024719] RSP: e02b:ffffc90062e3fc98 EFLAGS: 00010206
[189266.026720] RAX: 6c355a4e52423944 RBX: ffff88015d95c900 RCX: 0000000000000000
[189266.028827] RDX: 6c355a4e52423944 RSI: ffff88015d95cb78 RDI: ffff88015d95cb78
[189266.030933] RBP: ffff880521fe2120 R08: 0000000000000278 R09: ffff8805299d39c8
[189266.033009] R10: ffffc90062e3fd20 R11: 000000002f2eda00 R12: ffff88015d95c900
[189266.035091] R13: 0000000001000000 R14: ffff88015d95ed80 R15: 0000000000020000
[189266.037160] FS:  00007f731dacecc0(0000) GS:ffff880540a00000(0000) knlGS:0000000000000000
[189266.039344] CS:  e033 DS: 0000 ES: 0000 CR0: 0000000080050033
[189266.041345] CR2: 0000557410ffbd60 CR3: 00000004a0244000 CR4: 0000000000002660
[189266.043463] Call Trace:
[189266.045373]  vdev_queue_io_to_issue+0x397/0x870 [zfs]
[189266.047420]  vdev_queue_io_done+0x185/0x230 [zfs]
[189266.049427]  zio_vdev_io_done+0xca/0x1e0 [zfs]
[189266.051404]  zio_execute+0x87/0xe0 [zfs]
[189266.053282]  taskq_thread+0x2d8/0x500 [spl]
[189266.055123]  ? wake_up_q+0x70/0x70
[189266.056962]  ? zio_reexecute+0x390/0x390 [zfs]
[189266.058808]  kthread+0xf8/0x130
[189266.060561]  ? taskq_thread_spawn+0x50/0x50 [spl]
[189266.062398]  ? kthread_create_worker_on_cpu+0x70/0x70
[189266.064236]  ret_from_fork+0x35/0x40
[189266.066031] Code: 90 4c 8b 47 10 b9 01 00 00 00 29 d1 4c 01 c6 48 85 f6 48 89 f7 74 3c 48 63 d2 48 8b 04 d6 48 85 c0 74 19 48 63 c9 eb 03 48 89 d0 <48> 8b 14 c8 48 85 d2 75 f4 4c 29 c0 c3 39 d1 74 f8 48 8b 47 10
[189266.070321] RIP: avl_walk+0x2f/0x60 [zavl] RSP: ffffc90062e3fc98
[189266.072404] ---[ end trace 0eb462c311c1010f ]---
dweeezil commented 6 years ago

@johnkeates Are you by any chance using zfs_deadman_failmode=continue?

johnkeates commented 6 years ago

Nope, not using that AFAIK, unless it’s default. It’s a pretty simple and plain setup with all defaults; running three two-disk mirror pools, dedup off, compression lz4, root on zfs.

dweeezil commented 6 years ago

@johnkeates Might you have the event log (leading up to the hang) available? If you're running zed, it should log at least one line per event via syslog. Or, more ideally, the output of zpool events and/or zpool events -v.

johnkeates commented 6 years ago 
Sep 21 2018 13:29:32.013175881 sysevent.fs.zfs.history_event
Sep 21 2018 13:29:32.309175867 sysevent.fs.zfs.config_sync
Sep 21 2018 13:29:32.309175867 sysevent.fs.zfs.pool_import
Sep 21 2018 13:29:32.313175866 sysevent.fs.zfs.history_event
Sep 21 2018 13:29:32.577175853 sysevent.fs.zfs.config_sync
Sep 21 2018 13:29:44.113175286 sysevent.fs.zfs.history_event
Sep 21 2018 13:29:44.213175281 sysevent.fs.zfs.config_sync
Sep 21 2018 13:29:44.213175281 sysevent.fs.zfs.pool_import
Sep 21 2018 13:29:44.217175281 sysevent.fs.zfs.history_event
Sep 21 2018 13:29:44.265175279 sysevent.fs.zfs.config_sync
Sep 21 2018 13:29:45.749175206 sysevent.fs.zfs.history_event
Sep 21 2018 13:29:46.109175188 sysevent.fs.zfs.config_sync
Sep 21 2018 13:29:46.109175188 sysevent.fs.zfs.pool_import
Sep 21 2018 13:29:46.113175188 sysevent.fs.zfs.history_event
Sep 21 2018 13:29:46.417175173 sysevent.fs.zfs.config_sync

Sep 21 2018 13:29:44.113175286 sysevent.fs.zfs.history_event
        version = 0x0
        class = "sysevent.fs.zfs.history_event"
        pool = "fastpool"
        pool_guid = 0xf543bba1bec227e
        pool_state = 0x0
        pool_context = 0x0
        history_hostname = "xen-1-prod"
        history_internal_str = "pool version 5000; software version 5000/5; uts xen-1-prod 4.17.0-0.bpo.3-amd64 #1 SMP Debian 4.17.17-1~bpo9+1 (2018-08-27) x86_64"
        history_internal_name = "open"
        history_txg = 0x1245a32f
        history_time = 0x5ba4d628
        time = 0x5ba4d628 0x6beeaf6 
        eid = 0x6

Sep 21 2018 13:29:44.213175281 sysevent.fs.zfs.config_sync
        version = 0x0
        class = "sysevent.fs.zfs.config_sync"
        pool = "fastpool"
        pool_guid = 0xf543bba1bec227e
        pool_state = 0x0
        pool_context = 0x0
        time = 0x5ba4d628 0xcb4cbf1 
        eid = 0x7

Sep 21 2018 13:29:44.213175281 sysevent.fs.zfs.pool_import
        version = 0x0
        class = "sysevent.fs.zfs.pool_import"
        pool = "fastpool"
        pool_guid = 0xf543bba1bec227e
        pool_state = 0x0
        pool_context = 0x0
        time = 0x5ba4d628 0xcb4cbf1 
        eid = 0x8

Sep 21 2018 13:29:44.217175281 sysevent.fs.zfs.history_event
        version = 0x0
        class = "sysevent.fs.zfs.history_event"
        pool = "fastpool"
        pool_guid = 0xf543bba1bec227e
        pool_state = 0x0
        pool_context = 0x0
        history_hostname = "xen-1-prod"
        history_internal_str = "pool version 5000; software version 5000/5; uts xen-1-prod 4.17.0-0.bpo.3-amd64 #1 SMP Debian 4.17.17-1~bpo9+1 (2018-08-27) x86_64"
        history_internal_name = "import"
        history_txg = 0x1245a331
        history_time = 0x5ba4d628
        time = 0x5ba4d628 0xcf1d4f1 
        eid = 0x9

Sep 21 2018 13:29:44.265175279 sysevent.fs.zfs.config_sync
        version = 0x0
        class = "sysevent.fs.zfs.config_sync"
        pool = "fastpool"
        pool_guid = 0xf543bba1bec227e
        pool_state = 0x0
        pool_context = 0x0
        time = 0x5ba4d628 0xfce40ef 
        eid = 0xa
johnkeates commented 6 years ago

I'll check to see if I can get earlier messages, those are after the fact... argh

johnkeates commented 6 years ago

Can't seem to get logs before the system reboot, are they stored in a different location? kern.log has only this on ZFS & pool:

./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   32.716006] ZFS: Loaded module v0.7.9-3~bpo9+1, ZFS pool version 5000, ZFS filesystem version 5
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   32.970142] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x5000039fe6c3d56b-part1 (sdh): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   32.970738] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x5000039fe6cafb24-part1 (sdc): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   33.374010] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x5000039fe6cafb24-part1 (sdc): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   33.377180] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x5000039fe6c3d56b-part1 (sdh): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   45.483119] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x55cd2e414da94592-part1 (sdb): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   45.483137] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x55cd2e414da7dc87-part1 (sda): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   45.563873] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x5000cca37cef28f1-part1 (sdg): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   45.563922] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x5000cca37ce9cec7-part1 (sdd): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   46.216186] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x55cd2e414da7dc87-part1 (sda): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   46.218252] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x55cd2e414da94592-part1 (sdb): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   46.636142] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x5000cca37cef28f1-part1 (sdg): 256
./kern.log:Sep 21 13:29:49 xen-1-prod kernel: [   46.636161] ZFS: Unable to set "noop" scheduler for /dev/disk/by-id/wwn-0x5000cca37ce9cec7-part1 (sdd): 256
rincebrain commented 6 years ago

@johnkeates zed helpfully doesn't persist across reboots, because why would you ever want to keep logs.

grepping for zed in syslog/messages/... might log at least the short form of the events.

johnkeates commented 6 years ago

Yeah, that's what I did, and basically all the messages I got were the same as the ones logged in kern.log.

I wonder why there is no Zed log persistence, seems like logging 101...

stale[bot] commented 4 years ago

This issue has been automatically marked as "stale" because it has not had any activity for a while. It will be closed in 90 days if no further activity occurs. Thank you for your contributions.