System hang #3445
Comments
|
Happened again... May 29 14:33:52 zhead01 kernel: [202149.014855] general protection fault: 0000 [#1] SMP |
|
What were you doing when this happened ? zfs send or receive ? Are you using NFS ? how ? Please post more details for easier understanding and reproducibility Thanks |
|
This is an server with 60 sas disks attached in 6 disk raidz2, ~130TB pool. The server has 2 Xeon E5-2650's with 192GB of ram. The disks are connected through 2 LSI2905's. We are running zfs 0.6.4.1 but the pool is not upgraded yet with the new features. There are 69 volumes on this server which are exported with NFS3. The volumes contain various stuff like kvm images, storage for databases, and just big image files. We have about 2150 snapshots. Backups are running continously using zfs send, and no volumes are received. So it's hard to say what exactly was happening when the hang/crash happened. Every hour snapshots which are not transfered are created, most of the zfs send's run every 3 hours, just a handful are running hourly. Looking at the timestamp of the last 2 crashes, the hourly zfs send was running and had done a couple of volumes. The volume it was currently receiving is a 1.8T volume with lz4 compression and 16K recordsize. But, before these 2 I had one more crash during which no zfs send was running. Prevously the server was running kernel 3.2.65 with zfs 0.6.3-34-417104 (snapshot) happily without crashing. Hope this helps, or if more or other stuff is needed please ask. |
|
No zvols. Swap space is available, but it is not on zfs. It is on 'normal' disks. Ofcourse within the vm images that are exported through nfs there is swapspace, but I figure that might not be of any influence. Importing the pool after the hang took rather long. This kernel message was show while importing the pool: [202277.281763] SPL: using hostid 0x007f0101 |
|
@kernelOfTruth |
|
@kernelOfTruth This time a zfs snapshot was running when the pool hang. [540840.061790] INFO: task zfs:7850 blocked for more than 120 seconds. |
|
Just noticed, this time scrub was running as well. |
|
Just went back to v0.6.3-34-417104-wheezy which is my last known working version. One big difference I discovered is that importing the pool with this version takes ~30 seconds, while importing with zfs 0.6.4 and higher takes minutes. |
|
Have been running 10 days with v0.6.3-34-417104-wheezy now and still no crashes (knock on wood). So, it seems like a regression between commit 417104 and 0.6.4.1-release to me. |
|
CC'ing @dweeezil and @behlendorf on this issue I'm currently out of ideas but will look further - from time to time |
|
Today I had a problem which was similar to the previous problems I had. But now with v0.6.3-34-417104. This time an 2 day old snapshot got destroyed. The 'zfs destroy' command took about 20 minutes to get back to the prompt. All this time it was in 'D' state and pool IO almost grinded to an halt. Data could be read from the pool, but it was dreadfully slow. When the 'zfs destroy' command ended everything was back to normal. |
|
Tested with 0.6.4.2 and after 2 days zfs crashed again. [161884.389839] general protection fault: 0000 [#1] SMP |
|
@roedie thanks for the update. I took a look at this and it appears that somehow the dnode_hold succeeded yet returned a NULL dnode. I don't see how that can happen but the following patch should convert the panic in to just an IO error any may be a sufficient workaround until the root cause can be determined. diff --git a/module/zfs/dmu.c b/module/zfs/dmu.c
index 7e8328e..dc993fa 100644
--- a/module/zfs/dmu.c
+++ b/module/zfs/dmu.c
@@ -644,9 +644,13 @@ static int
dmu_free_long_range_impl(objset_t *os, dnode_t *dn, uint64_t offset,
uint64_t length)
{
- uint64_t object_size = (dn->dn_maxblkid + 1) * dn->dn_datablksz;
+ uint64_t object_size;
int err;
+ if (dn == NULL)
+ return (SET_ERROR(EINVAL));
+
+ object_size = (dn->dn_maxblkid + 1) * dn->dn_datablksz;
if (offset >= object_size)
return (0);
|
|
Great! I will apply this on top of 0.6.4.2, wait for a small maintenance window and see what happens. |
|
@behlendorf I've rebooted the server into 0.6.4.2 with your patch. Lets see what happens. |
|
@behlendorf The server has been running longer than before. Should something be logged when the bug is hit? |
|
something along or your previous error messages if nothing's coming up - it appears to work =) any stalls, hangs, etc. that you observe during operation ? |
A NULL should never be passed as the dnode_t pointer to the function dmu_free_long_range_impl(). Regardless, because we have a reported occurrence of this let's add some error handling to catch this. Better to report a reasonable error to caller than panic the system. Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov> Issue openzfs#3445
|
@roedie an error will be logged to the internal tracepoint buffer but that will be all. In your case, when the error is hit the offending object will just be skipped and left on the unlinked set. That's pretty benign. At worst it will cost you a little free space assuming the error is persistent. If it was transient then it will be cleaned up properly like all the other files you've removed. I've opened #3627 with the patch. |
…mpl() A NULL should never be passed as the dnode_t pointer to the function dmu_free_long_range_impl(). Regardless, because we have a reported occurrence of this let's add some error handling to catch this. Better to report a reasonable error to caller than panic the system. Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov> Issue openzfs#3445
A NULL should never be passed as the dnode_t pointer to the function dmu_free_long_range_impl(). Regardless, because we have a reported occurrence of this let's add some error handling to catch this. Better to report a reasonable error to caller than panic the system. Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov> Issue openzfs#3445
…mpl() A NULL should never be passed as the dnode_t pointer to the function dmu_free_long_range_impl(). Regardless, because we have a reported occurrence of this let's add some error handling to catch this. Better to report a reasonable error to caller than panic the system. Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov> Issue openzfs#3445
…mpl() A NULL should never be passed as the dnode_t pointer to the function dmu_free_long_range_impl(). Regardless, because we have a reported occurrence of this let's add some error handling to catch this. Better to report a reasonable error to caller than panic the system. Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov> Issue openzfs#3445
…mpl() A NULL should never be passed as the dnode_t pointer to the function dmu_free_long_range_impl(). Regardless, because we have a reported occurrence of this let's add some error handling to catch this. Better to report a reasonable error to caller than panic the system. Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov> Issue openzfs#3445
A NULL should never be passed as the dnode_t pointer to the function dmu_free_long_range_impl(). Regardless, because we have a reported occurrence of this let's add some error handling to catch this. Better to report a reasonable error to caller than panic the system. Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov> Issue openzfs#3445
|
@behlendorf After months of uptime I suddenly hit this bug again. The system was still running 0.6.4.2 with your patch applied. The only new thing is is the 'Firmware does not respond in time'. which is probably not ZFS related. |
|
@behlendorf And again today... I've got a hunch this has something to do with running solr/lucene over NFSv3 on a volume with 16K recordsize. But not sure yet. I'm a bit hesitant to upgrade to 0.6.5.3 since I have other hangs on servers using that version... |
and others
I'm not sure if this is a kernel bug, or if it is ZFS related. Debian Stock kernel 3.2.68 + ZFS 0.6.4-1.1-1-wheezy
508906] general protection fault: 0000 [#1] SMP
[530350.508927] CPU 5
[530350.508934] Modules linked in: 8021q garp stp bonding nfsd nfs nfs_acl auth_rpcgss fscache lockd sunrpc dm_service_time dm_multipath scsi_dh loop coretemp crc32c_intel ghash_clmulni_intel aesni_intel aes_x86_64 psmouse aes_generic snd_pcm serio_raw snd_page_alloc snd_timer snd cryptd soundcore pcspkr joydev hpilo hpwdt sb_edac edac_core evdev iTCO_wdt iTCO_vendor_support ioatdma dca zfs(P) zunicode(P) zavl(P) zcommon(P) znvpair(P) spl(O) zlib_deflate container acpi_power_meter button processor ext4 crc16 jbd2 mbcache dm_mod microcode ses enclosure ata_generic usbhid hid uhci_hcd sg sd_mod crc_t10dif mpt2sas raid_class scsi_transport_sas ata_piix ehci_hcd libata usbcore bnx2x usb_common hpsa mdio thermal scsi_mod tg3 crc32c thermal_sys libcrc32c libphy [last unloaded: scsi_wait_scan]
[530350.509486]
[530350.509505] Pid: 46221, comm: nfsd Tainted: P W O 3.2.0-4-amd64 #1 Debian 3.2.68-1+deb7u1 HP ProLiant DL360p Gen8
[530350.509553] RIP: 0010:[] [] dbuf_free_range+0xd5/0x4af [zfs]
[530350.509612] RSP: 0018:ffff88174ce69b00 EFLAGS: 00010282
[530350.509635] RAX: dead000000100008 RBX: dead000000100008 RCX: dead000000100008
[530350.509671] RDX: 00000000000000f8 RSI: ffff880392ae5388 RDI: ffff880392ae5350
[530350.509706] RBP: ffff880a5ac6c878 R08: ffff880a8eca23e0 R09: ffff880a8eca23e0
[530350.509742] R10: ffff8810249b01d0 R11: ffff8810249b01d0 R12: 0000000000000000
[530350.509778] R13: 0000000000000eb8 R14: ffff88109ac500c0 R15: ffff88176d802300
[530350.509814] FS: 0000000000000000(0000) GS:ffff88183faa0000(0000) knlGS:0000000000000000
[530350.509851] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[530350.509874] CR2: 00007fd215dfc000 CR3: 00000017d53aa000 CR4: 00000000000406e0
[530350.509910] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[530350.509946] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[530350.509983] Process nfsd (pid: 46221, threadinfo ffff88174ce68000, task ffff88176ea9c040)
[530350.510019] Stack:
[530350.510037] 0000000000000000 ffffffffa0636f90 ffff880a5ac6cac8 0000000000000000
[530350.510090] ffff88176ea9c040 0100000000000248 0000000000fde037 ffff880a5ac6cb08
[530350.510143] 0000000000fde037 dead000000100008 ffff88176ea9c040 ffff88176ea9c040
[530350.510195] Call Trace:
[530350.510235] [] ? range_tree_add+0x20c/0x21f [zfs]
[530350.510273] [] ? dnode_free_range+0x40e/0x44b [zfs]
[530350.510308] [] ? dmu_free_long_range+0x183/0x1db [zfs]
[530350.510335] [] ? should_resched+0x5/0x23
[530350.510374] [] ? zfs_rmnode+0x61/0x2b8 [zfs]
[530350.510413] [] ? zfs_zinactive+0xb3/0x139 [zfs]
[530350.510452] [] ? zfs_inactive+0x130/0x169 [zfs]
[530350.510488] [] ? zpl_evict_inode+0x3e/0x4c [zfs]
[530350.510514] [] ? evict+0x96/0x148
[530350.510537] [] ? d_delete+0xdc/0xff
[530350.510561] [] ? vfs_unlink+0xb0/0xbb
[530350.510588] [] ? nfsd_unlink+0xea/0x145 [nfsd]
[530350.510616] [] ? nfsd3_proc_remove+0x76/0xbc [nfsd]
[530350.510643] [] ? nfsd_dispatch+0xd7/0x1ba [nfsd]
[530350.510672] [] ? svc_process_common+0x2c3/0x4c4 [sunrpc]
[530350.510698] [] ? try_to_wake_up+0x197/0x197
[530350.510725] [] ? svc_process+0x110/0x12c [sunrpc]
[530350.510751] [] ? nfsd+0xe3/0x127 [nfsd]
[530350.510776] [] ? 0xffffffffa04cffff
[530350.510800] [] ? kthread+0x76/0x7e
[530350.510825] [] ? kernel_thread_helper+0x4/0x10
[530350.510851] [] ? kthread_worker_fn+0x139/0x139
[530350.510875] [] ? gs_change+0x13/0x13
[530350.510897] Code: 8d 90 02 00 00 31 db 48 89 4c 24 38 48 39 c8 0f 84 98 03 00 00 48 89 c3 48 2b 9d 88 02 00 00 e9 89 03 00 00 48 8b 95 88 02 00 00 <48> 8b 04 13 48 89 c1 48 29 d1 48 3b 44 24 38 b8 00 00 00 00 48
[530350.511212] RIP [] dbuf_free_range+0xd5/0x4af [zfs]
[530350.511248] RSP
[530350.511659] ---[ end trace 3eb43d768f339f85 ]---
The text was updated successfully, but these errors were encountered: