From owner-freebsd-fs@freebsd.org Thu Oct 15 14:56:28 2015 Return-Path: Delivered-To: freebsd-fs@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id EE4C7A15AD8 for ; Thu, 15 Oct 2015 14:56:27 +0000 (UTC) (envelope-from karl@denninger.net) Received: from mail.denninger.net (wsip-70-169-168-7.pn.at.cox.net [70.169.168.7]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 97D40809 for ; Thu, 15 Oct 2015 14:56:26 +0000 (UTC) (envelope-from karl@denninger.net) Received: from [192.168.1.40] (Karl-Desktop.Denninger.net [192.168.1.40]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by mail.denninger.net (Postfix) with ESMTPSA id E3EA11C13C1 for ; Thu, 15 Oct 2015 09:56:24 -0500 (CDT) Subject: Re: Panic in ZFS during zfs recv (while snapshots being destroyed) To: freebsd-fs@freebsd.org References: <55BB443E.8040801@denninger.net> <55CF7926.1030901@denninger.net> <55DF7191.2080409@denninger.net> <55DF76AA.3040103@denninger.net> <561FB7D0.4080107@denninger.net> From: Karl Denninger X-Enigmail-Draft-Status: N1110 Message-ID: <561FBE95.6010107@denninger.net> Date: Thu, 15 Oct 2015 09:56:21 -0500 User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:38.0) Gecko/20100101 Thunderbird/38.3.0 MIME-Version: 1.0 In-Reply-To: <561FB7D0.4080107@denninger.net> Content-Type: multipart/signed; protocol="application/pkcs7-signature"; micalg=sha-512; boundary="------------ms070409030504010001090508" X-Content-Filtered-By: Mailman/MimeDel 2.1.20 X-BeenThere: freebsd-fs@freebsd.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: Filesystems List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 15 Oct 2015 14:56:28 -0000 This is a cryptographically signed message in MIME format. --------------ms070409030504010001090508 Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: quoted-printable More data on this -- it is happening during this sequence (snippet from my backup scripts w/my comments) "$i" is the ZFS filesystem that is being backed up; in each case the crashes occur _*only*_ when the root (mounted) filesystem is being copied; it has never happened on any of the other datasets. zfs rename -r $i@zfs-base $i@zfs-old (rename the previous backup base to the "start" point) zfs snapshot -r $i@zfs-base (take a snapshot to checkpoint to on the back= up) zfs send -RI $i@zfs-old $i@zfs-base | zfs receive -Fudv $BACKUP result=3D$? if [ $result -eq 0 ]; then _*zfs destroy -r $i@zfs-old*_ -->> *PANIC OCCURS HERE* zfs destroy -r $BACKUP/$FILESYS@zfs-old else echo "STOP - - ERROR RUNNING COPY on $i!!!!" exit 1 fi On 10/15/2015 09:27, Karl Denninger wrote: > Got another one of these this morning, after a long absence... > > Same symptom -- happened during a backup (send/receive) and it's in > the same place -- when the snapshot is unmounted and destroyed. I > have a clean dump and this is against a quite-recent checkout, so the > most-currently-rolled forward ZFS changes are in this kernel. > > > Fatal trap 12: page fault while in kernel mode > cpuid =3D 14; apic id =3D 34 > fault virtual address =3D 0x378 > fault code =3D supervisor read data, page not present > instruction pointer =3D 0x20:0xffffffff80940ae0 > stack pointer =3D 0x28:0xfffffe066796c680 > frame pointer =3D 0x28:0xfffffe066796c700 > code segment =3D base 0x0, limit 0xfffff, type 0x1b > =3D DPL 0, pres 1, long 1, def32 0, gran 1 > processor eflags =3D interrupt enabled, resume, IOPL =3D 0 > current process =3D 81187 (zfs) > trap number =3D 12 > panic: page fault > cpuid =3D 14 > KDB: stack backtrace: > db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame > 0xfffffe066796c160 > kdb_backtrace() at kdb_backtrace+0x39/frame 0xfffffe066796c210 > vpanic() at vpanic+0x126/frame 0xfffffe066796c250 > panic() at panic+0x43/frame 0xfffffe066796c2b0 > trap_fatal() at trap_fatal+0x36b/frame 0xfffffe066796c310 > trap_pfault() at trap_pfault+0x2ed/frame 0xfffffe066796c3b0 > trap() at trap+0x47a/frame 0xfffffe066796c5c0 > calltrap() at calltrap+0x8/frame 0xfffffe066796c5c0 > --- trap 0xc, rip =3D 0xffffffff80940ae0, rsp =3D 0xfffffe066796c680, r= bp > =3D 0xfffffe > 066796c700 --- > *__mtx_lock_sleep() at __mtx_lock_sleep+0x1b0/frame 0xfffffe066796c700*= > dounmount() at dounmount+0x58/frame 0xfffffe066796c780 > zfs_unmount_snap() at zfs_unmount_snap+0x114/frame 0xfffffe066796c7a0 > dsl_dataset_user_release_impl() at > dsl_dataset_user_release_impl+0x103/frame 0xf > ffffe066796c920 > dsl_dataset_user_release_onexit() at > dsl_dataset_user_release_onexit+0x5c/frame > 0xfffffe066796c940 > zfs_onexit_destroy() at zfs_onexit_destroy+0x56/frame 0xfffffe066796c97= 0 > zfsdev_close() at zfsdev_close+0x52/frame 0xfffffe066796c990 > devfs_fpdrop() at devfs_fpdrop+0xa9/frame 0xfffffe066796c9b0 > devfs_close_f() at devfs_close_f+0x45/frame 0xfffffe066796c9e0 > _fdrop() at _fdrop+0x29/frame 0xfffffe066796ca00 > closef() at closef+0x21e/frame 0xfffffe066796ca90 > closefp() at closefp+0x98/frame 0xfffffe066796cad0 > amd64_syscall() at amd64_syscall+0x35d/frame 0xfffffe066796cbf0 > Xfast_syscall() at Xfast_syscall+0xfb/frame 0xfffffe066796cbf0 > --- syscall (6, FreeBSD ELF64, sys_close), rip =3D 0x801a01f5a, rsp =3D= > 0x7fffffffd728, rbp =3D 0x7fffffffd740 --- > Uptime: 3d15h37m26s > > > On 8/27/2015 15:44, Karl Denninger wrote: >> No, but that does sound like it might be involved..... >> >> And yeah, this did start when I moved the root pool to a mirrored pair= >> of Intel 530s off a pair of spinning-rust WD RE4s.... (The 530s are da= rn >> nice performance-wise, reasonably inexpensive and thus very suitable f= or >> a root filesystem drive and they also pass the "pull the power cord" >> test, incidentally.) >> >> You may be onto something -- I'll try shutting it off, but due to the >> fact that I can't make this happen and it's a "every week or two" pani= c, >> but ALWAYS when the zfs send | zfs recv is running AND it's always on >> the same filesystem it will be a fair while before I know if it's fixe= d >> (like over a month, given the usual pattern here, as that would be 4 >> "average" periods without a panic)..... >> >> I also wonder if I could tune this out with some of the other TRIM >> parameters instead of losing it entirely. >> >> vfs.zfs.trim.max_interval: 1 >> vfs.zfs.trim.timeout: 30 >> vfs.zfs.trim.txg_delay: 32 >> vfs.zfs.trim.enabled: 1 >> vfs.zfs.vdev.trim_max_pending: 10000 >> vfs.zfs.vdev.trim_max_active: 64 >> vfs.zfs.vdev.trim_min_active: 1 >> >> That it's panic'ing on a mtx_lock_sleep might point this way.... the >> trace shows it coming from a zfs_onexit_destroy, which ends up calling= >> zfs_unmount_snap() and then it blows in dounmount() while executing >> mtx_lock_sleep(). >> >> I do wonder if I'm begging for new and innovative performance issues i= f >> I run with TRIM off for an extended period of time, however..... :-) >> >> >> On 8/27/2015 15:30, Sean Chittenden wrote: >>> Have you tried disabling TRIM? We recently ran in to an issue where = a `zfs delete` on a large dataset caused the host to panic because TRIM w= as tripping over the ZFS deadman timer. Disabling TRIM worked as valid = workaround for us. ? You mentioned a recent move to SSDs, so this can h= appen, esp after the drive has experienced a little bit of actual work. = ? -sc >>> >>> >>> -- >>> Sean Chittenden >>> sean@chittenden.org >>> >>> >>>> On Aug 27, 2015, at 13:22, Karl Denninger wrote= : >>>> >>>> On 8/15/2015 12:38, Karl Denninger wrote: >>>>> Update: >>>>> >>>>> This /appears /to be related to attempting to send or receive a >>>>> /cloned /snapshot. >>>>> >>>>> I use /beadm /to manage boot environments and the crashes have all >>>>> come while send/recv-ing the root pool, which is the one where thes= e >>>>> clones get created. It is /not /consistent within a given snapshot= >>>>> when it crashes and a second attempt (which does a "recovery" >>>>> send/receive) succeeds every time -- I've yet to have it panic twic= e >>>>> sequentially. >>>>> >>>>> I surmise that the problem comes about when a file in the cloned >>>>> snapshot is modified, but this is a guess at this point. >>>>> >>>>> I'm going to try to force replication of the problem on my test sys= tem. >>>>> >>>>> On 7/31/2015 04:47, Karl Denninger wrote: >>>>>> I have an automated script that runs zfs send/recv copies to bring= a >>>>>> backup data set into congruence with the running copies nightly. = The >>>>>> source has automated snapshots running on a fairly frequent basis >>>>>> through zfs-auto-snapshot. >>>>>> >>>>>> Recently I have started having a panic show up about once a week d= uring >>>>>> the backup run, but it's inconsistent. It is in the same place, b= ut I >>>>>> cannot force it to repeat. >>>>>> >>>>>> The trap itself is a page fault in kernel mode in the zfs code at >>>>>> zfs_unmount_snap(); here's the traceback from the kvm (sorry for t= he >>>>>> image link but I don't have a better option right now.) >>>>>> >>>>>> I'll try to get a dump, this is a production machine with encrypte= d swap >>>>>> so it's not normally turned on. >>>>>> >>>>>> Note that the pool that appears to be involved (the backup pool) h= as >>>>>> passed a scrub and thus I would assume the on-disk structure is ok= =2E.... >>>>>> but that might be an unfair assumption. It is always occurring in= the >>>>>> same dataset although there are a half-dozen that are sync'd -- if= this >>>>>> one (the first one) successfully completes during the run then all= the >>>>>> rest will as well (that is, whenever I restart the process it has = always >>>>>> failed here.) The source pool is also clean and passes a scrub. >>>>>> >>>>>> traceback is at http://www.denninger.net/kvmimage.png; apologies f= or the >>>>>> image traceback but this is coming from a remote KVM. >>>>>> >>>>>> I first saw this on 10.1-STABLE and it is still happening on FreeB= SD >>>>>> 10.2-PRERELEASE #9 r285890M, which I updated to in an attempt to s= ee if >>>>>> the problem was something that had been addressed. >>>>>> >>>>>> >>>>> --=20 >>>>> Karl Denninger >>>>> karl@denninger.net >>>>> /The Market Ticker/ >>>>> /[S/MIME encrypted email preferred]/ >>>> Second update: I have now taken another panic on 10.2-Stable, same d= eal, >>>> but without any cloned snapshots in the source image. I had thought = that >>>> removing cloned snapshots might eliminate the issue; that is now out= the >>>> window. >>>> >>>> It ONLY happens on this one filesystem (the root one, incidentally) >>>> which is fairly-recently created as I moved this machine from spinni= ng >>>> rust to SSDs for the OS and root pool -- and only when it is being >>>> backed up by using zfs send | zfs recv (with the receive going to a >>>> different pool in the same machine.) I have yet to be able to provo= ke >>>> it when using zfs send to copy to a different machine on the same LA= N, >>>> but given that it is not able to be reproduced on demand I can't be >>>> certain it's timing related (e.g. performance between the two pools = in >>>> question) or just that I haven't hit the unlucky combination. >>>> >>>> This looks like some sort of race condition and I will continue to s= ee >>>> if I can craft a case to make it occur "on demand" >>>> >>>> --=20 >>>> Karl Denninger >>>> karl@denninger.net >>>> /The Market Ticker/ >>>> /[S/MIME encrypted email preferred]/ >>> %SPAMBLOCK-SYS: Matched [+Sean Chittenden ], mes= sage ok >>> > > --=20 > Karl Denninger > karl@denninger.net > /The Market Ticker/ > /[S/MIME encrypted email preferred]/ --=20 Karl Denninger karl@denninger.net /The Market Ticker/ /[S/MIME encrypted email preferred]/ --------------ms070409030504010001090508 Content-Type: application/pkcs7-signature; name="smime.p7s" Content-Transfer-Encoding: base64 Content-Disposition: attachment; filename="smime.p7s" Content-Description: S/MIME Cryptographic Signature MIAGCSqGSIb3DQEHAqCAMIACAQExDzANBglghkgBZQMEAgMFADCABgkqhkiG9w0BBwEAAKCC Bl8wggZbMIIEQ6ADAgECAgEpMA0GCSqGSIb3DQEBCwUAMIGQMQswCQYDVQQGEwJVUzEQMA4G A1UECBMHRmxvcmlkYTESMBAGA1UEBxMJTmljZXZpbGxlMRkwFwYDVQQKExBDdWRhIFN5c3Rl bXMgTExDMRwwGgYDVQQDExNDdWRhIFN5c3RlbXMgTExDIENBMSIwIAYJKoZIhvcNAQkBFhND dWRhIFN5c3RlbXMgTExDIENBMB4XDTE1MDQyMTAyMjE1OVoXDTIwMDQxOTAyMjE1OVowWjEL MAkGA1UEBhMCVVMxEDAOBgNVBAgTB0Zsb3JpZGExGTAXBgNVBAoTEEN1ZGEgU3lzdGVtcyBM TEMxHjAcBgNVBAMTFUthcmwgRGVubmluZ2VyIChPQ1NQKTCCAiIwDQYJKoZIhvcNAQEBBQAD ggIPADCCAgoCggIBALmEWPhAdphrWd4K5VTvE5pxL3blRQPyGF3ApjUjgtavqU1Y8pbI3Byg XDj2/Uz9Si8XVj/kNbKEjkRh5SsNvx3Fc0oQ1uVjyCq7zC/kctF7yLzQbvWnU4grAPZ3IuAp 3/fFxIVaXpxEdKmyZAVDhk9az+IgHH43rdJRIMzxJ5vqQMb+n2EjadVqiGPbtG9aZEImlq7f IYDTnKyToi23PAnkPwwT+q1IkI2DTvf2jzWrhLR5DTX0fUYC0nxlHWbjgpiapyJWtR7K2YQO aevQb/3vN9gSojT2h+cBem7QIj6U69rEYcEDvPyCMXEV9VcXdcmW42LSRsPvZcBHFkWAJqMZ Myiz4kumaP+s+cIDaXitR/szoqDKGSHM4CPAZV9Yh8asvxQL5uDxz5wvLPgS5yS8K/o7zDR5 vNkMCyfYQuR6PAJxVOk5Arqvj9lfP3JSVapwbr01CoWDBkpuJlKfpQIEeC/pcCBKknllbMYq yHBO2TipLyO5Ocd1nhN/nOsO+C+j31lQHfOMRZaPQykXVPWG5BbhWT7ttX4vy5hOW6yJgeT/ o3apynlp1cEavkQRS8uJHoQszF6KIrQMID/JfySWvVQ4ksnfzwB2lRomrdrwnQ4eG/HBS+0l eozwOJNDIBlAP+hLe8A5oWZgooIIK/SulUAsfI6Sgd8dTZTTYmlhAgMBAAGjgfQwgfEwNwYI KwYBBQUHAQEEKzApMCcGCCsGAQUFBzABhhtodHRwOi8vY3VkYXN5c3RlbXMubmV0Ojg4ODgw CQYDVR0TBAIwADARBglghkgBhvhCAQEEBAMCBaAwCwYDVR0PBAQDAgXgMCwGCWCGSAGG+EIB DQQfFh1PcGVuU1NMIEdlbmVyYXRlZCBDZXJ0aWZpY2F0ZTAdBgNVHQ4EFgQUxRyULenJaFwX RtT79aNmIB/u5VkwHwYDVR0jBBgwFoAUJHGbnYV9/N3dvbDKkpQDofrTbTUwHQYDVR0RBBYw FIESa2FybEBkZW5uaW5nZXIubmV0MA0GCSqGSIb3DQEBCwUAA4ICAQBPf3cYtmKowmGIYsm6 eBinJu7QVWvxi1vqnBz3KE+HapqoIZS8/PolB/hwiY0UAE1RsjBJ7yEjihVRwummSBvkoOyf G30uPn4yg4vbJkR9lTz8d21fPshWETa6DBh2jx2Qf13LZpr3Pj2fTtlu6xMYKzg7cSDgd2bO sJGH/rcvva9Spkx5Vfq0RyOrYph9boshRN3D4tbWgBAcX9POdXCVfJONDxhfBuPHsJ6vEmPb An+XL5Yl26XYFPiODQ+Qbk44Ot1kt9s7oS3dVUrh92Qv0G3J3DF+Vt6C15nED+f+bk4gScu+ JHT7RjEmfa18GT8DcT//D1zEke1Ymhb41JH+GyZchDRWtjxsS5OBFMzrju7d264zJUFtX7iJ 3xvpKN7VcZKNtB6dLShj3v/XDsQVQWXmR/1YKWZ93C3LpRs2Y5nYdn6gEOpL/WfQFThtfnat HNc7fNs5vjotaYpBl5H8+VCautKbGOs219uQbhGZLYTv6okuKcY8W+4EJEtK0xB08vqr9Jd0 FS9MGjQE++GWo+5eQxFt6nUENHbVYnsr6bYPQsZH0CRNycgTG9MwY/UIXOf4W034UpR82TBG 1LiMsYfb8ahQJhs3wdf1nzipIjRwoZKT1vGXh/cj3gwSr64GfenURBxaFZA5O1acOZUjPrRT n3ci4McYW/0WVVA3lDGCBRMwggUPAgEBMIGWMIGQMQswCQYDVQQGEwJVUzEQMA4GA1UECBMH RmxvcmlkYTESMBAGA1UEBxMJTmljZXZpbGxlMRkwFwYDVQQKExBDdWRhIFN5c3RlbXMgTExD MRwwGgYDVQQDExNDdWRhIFN5c3RlbXMgTExDIENBMSIwIAYJKoZIhvcNAQkBFhNDdWRhIFN5 c3RlbXMgTExDIENBAgEpMA0GCWCGSAFlAwQCAwUAoIICTTAYBgkqhkiG9w0BCQMxCwYJKoZI hvcNAQcBMBwGCSqGSIb3DQEJBTEPFw0xNTEwMTUxNDU2MjFaME8GCSqGSIb3DQEJBDFCBEB4 3DB4wJHGvHDPgNx5fUUOw4hKGEKCCIasQykFb/OMA/GsM6rTpjHcYcY8jIdlTzV8OZzMMbdk bhS6uAn2HCpZMGwGCSqGSIb3DQEJDzFfMF0wCwYJYIZIAWUDBAEqMAsGCWCGSAFlAwQBAjAK BggqhkiG9w0DBzAOBggqhkiG9w0DAgICAIAwDQYIKoZIhvcNAwICAUAwBwYFKw4DAgcwDQYI KoZIhvcNAwICASgwgacGCSsGAQQBgjcQBDGBmTCBljCBkDELMAkGA1UEBhMCVVMxEDAOBgNV BAgTB0Zsb3JpZGExEjAQBgNVBAcTCU5pY2V2aWxsZTEZMBcGA1UEChMQQ3VkYSBTeXN0ZW1z IExMQzEcMBoGA1UEAxMTQ3VkYSBTeXN0ZW1zIExMQyBDQTEiMCAGCSqGSIb3DQEJARYTQ3Vk YSBTeXN0ZW1zIExMQyBDQQIBKTCBqQYLKoZIhvcNAQkQAgsxgZmggZYwgZAxCzAJBgNVBAYT AlVTMRAwDgYDVQQIEwdGbG9yaWRhMRIwEAYDVQQHEwlOaWNldmlsbGUxGTAXBgNVBAoTEEN1 ZGEgU3lzdGVtcyBMTEMxHDAaBgNVBAMTE0N1ZGEgU3lzdGVtcyBMTEMgQ0ExIjAgBgkqhkiG 9w0BCQEWE0N1ZGEgU3lzdGVtcyBMTEMgQ0ECASkwDQYJKoZIhvcNAQEBBQAEggIAeODoQB3f 52IrW9FEYbHbpenZJ1dVfft8ZtowOD7eHivRGWlPiRaym6RPPHhmLibZ/Gy09piVckZ6Dejy ySBnrAjbT8k2LIGkhIq3DrXW8ZUbPQDz+SsJD1NeXwIPbYLpgl1L/JlFueecRA2lcBFiXbM1 2UyGpBTH9XvhuTCEZpwW50fdHUqzS2eeXwE8wA+51LsBsMmFGJNo1RAIsxOVvIao1PudpVRM 1PxTCzpNvZ9u94r3FO4BH1Y8sKIBYn0ofPlr3Ij0/j09Z4paaavsFTA/vTHFi8MY6rImTkp1 yjmwC+9Cvj+C9z4vi0bNuRyvrVC91s5Gz+YPHjTtbk9jOYwTg5onWH+JiSD5Lh356wTTiZg7 hohx7sDUzK7vc9gJS1H74O6qv1pcQAAxIBQNPmkB3vKk7M7v6Hu/XXeugNuGstQH+YsgKtiq Je0WDJQYukl2Z1+R8gBT0fAH4GkLlLeAuvlGu3DTPJ7kklzEHY43NljlS+tb5PJNJmZsJT4r +Rmj8NMl80yA5bEGT2EiiFxOG3MOI1xEDk4/EyisfjmTe59q0oDmFAnWxZ0GgyLVtwzjWX1j YNL9CJxt/hlTL93lPAlrIW+lF+MeQ0qpIx0TBWGDn3SyEbExpCyKArkJMV395Q9XsgMVIF5H P3Et9bydEDwSSJ8IK9laXnBWpikAAAAAAAA= --------------ms070409030504010001090508--