Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SPLError: 864:0:(zfs_vfsops.c:347:zfs_space_delta_cb()) SPL PANIC #1303

Closed
ghost opened this issue Feb 19, 2013 · 18 comments
Closed

SPLError: 864:0:(zfs_vfsops.c:347:zfs_space_delta_cb()) SPL PANIC #1303

ghost opened this issue Feb 19, 2013 · 18 comments

Comments

@ghost
Copy link

ghost commented Feb 19, 2013

This system is running rc14 with only 3.5Gbyte of RAM. This happened during an rsync.

VERIFY3(sa.sa_magic == 0x2F505A) failed (1319160994 == 3100762)
SPLError: 864:0:(zfs_vfsops.c:347:zfs_space_delta_cb()) SPL PANIC
SPL: Showing stack for process 864
Pid: 864, comm: txg_sync Tainted: P           ---------------    2.6.32-279.22.1.el6.x86_64 #1
Call Trace:
[<ffffffffa02dd5a7>] ? spl_debug_dumpstack+0x27/0x40 [spl]
[<ffffffffa02dec81>] ? spl_debug_bug+0x81/0xd0 [spl]
[<ffffffffa0452226>] ? zfs_space_delta_cb+0x286/0x290 [zfs]
[<ffffffffa03ce5a9>] ? dbuf_rele_and_unlock+0x169/0x210 [zfs]
[<ffffffffa03dd235>] ? dmu_objset_userquota_get_ids+0xc5/0x420 [zfs]
[<ffffffff814eb4fe>] ? mutex_lock+0x1e/0x50
[<ffffffffa03eab83>] ? dnode_sync+0xa3/0xa60 [zfs]
[<ffffffffa03d13a9>] ? dbuf_sync_list+0x59/0x80 [zfs]
[<ffffffffa03eafef>] ? dnode_sync+0x50f/0xa60 [zfs]
[<ffffffff814eb4fe>] ? mutex_lock+0x1e/0x50
[<ffffffffa03da819>] ? dmu_objset_sync_dnodes+0x89/0xb0 [zfs]
[<ffffffffa03daa2f>] ? dmu_objset_sync+0x1ef/0x360 [zfs]
[<ffffffffa03d9b20>] ? dmu_objset_write_ready+0x0/0x50 [zfs]
[<ffffffffa03daba0>] ? dmu_objset_write_done+0x0/0x70 [zfs]
[<ffffffffa03ed03c>] ? dsl_dataset_sync+0x4c/0x60 [zfs]
[<ffffffffa03fc1bf>] ? dsl_pool_sync+0xcf/0x540 [zfs]
[<ffffffffa041047e>] ? spa_sync+0x39e/0xa00 [zfs]
[<ffffffff8105f8ac>] ? try_to_wake_up+0x24c/0x3e0
[<ffffffff81012a69>] ? read_tsc+0x9/0x20
[<ffffffffa0422d87>] ? txg_sync_thread+0x307/0x590 [zfs]
[<ffffffff810527f9>] ? set_user_nice+0xc9/0x130
[<ffffffffa0422a80>] ? txg_sync_thread+0x0/0x590 [zfs]
[<ffffffffa02e64d8>] ? thread_generic_wrapper+0x68/0x80 [spl]
[<ffffffffa02e6470>] ? thread_generic_wrapper+0x0/0x80 [spl]
[<ffffffff81090876>] ? kthread+0x96/0xa0
[<ffffffff8100c0ca>] ? child_rip+0xa/0x20
[<ffffffff810907e0>] ? kthread+0x0/0xa0
[<ffffffff8100c0c0>] ? child_rip+0x0/0x20
SPL: Dumping log to /tmp/spl-log.1361200575.864

The log is at http://wwwlehre.dhbw-stuttgart.de/~bziller/spl-log.1361200575.864.gz

@behlendorf
Copy link
Contributor

The offending VERIFY was recently introduced by a94addd which was a back ported fix from Illumos, see https://www.illumos.org/issues/3208. @ahrens any thoughts on this? Was there a follow fix we perhaps missed?

@maxximino
Copy link
Contributor

@behlendorf look at that numbers in binary:

1001110101000001100110010100010 = 1319160994
1011110101000001011010          = 3100762

They are suspiciously similar.
The problem could be caused by memory corruption (as you've noticed in issue #1263 ?)

@ahrens
Copy link
Member

ahrens commented Feb 20, 2013

@behlendorf I haven't seen this before, and there was no follow-on fix. Can you get a crash dump and examine the rest of the sa structure to see if it seems to be correct aside from the sa_magic? Or use zdb to examine the on-disk state and see if it still has an invalid sa_magic?

@maxximino How exactly are those numbers (0x2f505a and 0x4ea0cca2) similar? They have no (nonzero) bytes in common.

@ghost
Copy link
Author

ghost commented Feb 25, 2013

I'm sorry, behlendorf, maxximo, ahrens.
This SPLerror must relate to jimmyH/zfs@c8d5f5a which added L2ARC compression. It did run fine at first for some weeks. But now after disabling L2ARC compression, the error doesn't occur any longer.

@ghost ghost closed this as completed Feb 25, 2013
@behlendorf
Copy link
Contributor

@bziller Thanks for following up and letting us know.

@skiselkov
Copy link
Contributor

@bziller I highly doubt that this was caused by L2ARC compression, since buffer corruption in L2ARC traversal would have been caught by the L2ARC checksum, since we compress after checksumming and verify after decompression - see lines 4811 and 4853 in jimmyH/zfs@c8d5f5a for the compression side and lines 4442 and 4448 for the decompression side.

@ghost
Copy link
Author

ghost commented Feb 26, 2013

@skiselkov You're right, because I just got a SPL Panic again with a plain rc14 install. Sorry again :(

Feb 26 08:26:32 moria kernel: VERIFY3(sa.sa_magic == 0x2F505A) failed (1281434586 == 3100762)
Feb 26 08:26:32 moria kernel: SPLError: 29875:0:(zfs_vfsops.c:347:zfs_space_delta_cb()) SPL PANIC
Feb 26 08:26:32 moria kernel: SPL: Showing stack for process 29875
Feb 26 08:26:32 moria kernel: Pid: 29875, comm: txg_sync Tainted: P           ---------------    2.6.32-279.22.1.el6.x86_64 #1
Feb 26 08:26:32 moria kernel: Call Trace:
Feb 26 08:26:32 moria kernel: [<ffffffffa04dd5a7>] ? spl_debug_dumpstack+0x27/0x40 [spl]
Feb 26 08:26:32 moria kernel: [<ffffffffa04dec81>] ? spl_debug_bug+0x81/0xd0 [spl]
Feb 26 08:26:32 moria kernel: [<ffffffffa06dcc36>] ? zfs_space_delta_cb+0x286/0x290 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa06591d9>] ? dbuf_rele_and_unlock+0x169/0x210 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa0667c45>] ? dmu_objset_userquota_get_ids+0xc5/0x420 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffff814eb4fe>] ? mutex_lock+0x1e/0x50
Feb 26 08:26:32 moria kernel: [<ffffffffa0675593>] ? dnode_sync+0xa3/0xa60 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa065bf19>] ? dbuf_sync_list+0x59/0x80 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffff814eb4fe>] ? mutex_lock+0x1e/0x50
Feb 26 08:26:32 moria kernel: [<ffffffffa06652e9>] ? dmu_objset_sync_dnodes+0x89/0xb0 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa06654dd>] ? dmu_objset_sync+0x1cd/0x330 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa06645f0>] ? dmu_objset_write_ready+0x0/0x50 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa0665640>] ? dmu_objset_write_done+0x0/0x70 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa0677a4c>] ? dsl_dataset_sync+0x4c/0x60 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa0686bcf>] ? dsl_pool_sync+0xcf/0x540 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa069ae8e>] ? spa_sync+0x39e/0xa00 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffff8105f8ac>] ? try_to_wake_up+0x24c/0x3e0
Feb 26 08:26:32 moria kernel: [<ffffffff81012a69>] ? read_tsc+0x9/0x20
Feb 26 08:26:32 moria kernel: [<ffffffffa06ad797>] ? txg_sync_thread+0x307/0x590 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffff810527f9>] ? set_user_nice+0xc9/0x130
Feb 26 08:26:32 moria kernel: [<ffffffffa06ad490>] ? txg_sync_thread+0x0/0x590 [zfs]
Feb 26 08:26:32 moria kernel: [<ffffffffa04e64d8>] ? thread_generic_wrapper+0x68/0x80 [spl]
Feb 26 08:26:32 moria kernel: [<ffffffffa04e6470>] ? thread_generic_wrapper+0x0/0x80 [spl]
Feb 26 08:26:32 moria kernel: [<ffffffff81090876>] ? kthread+0x96/0xa0
Feb 26 08:26:32 moria kernel: [<ffffffff8100c0ca>] ? child_rip+0xa/0x20
Feb 26 08:26:32 moria kernel: [<ffffffff810907e0>] ? kthread+0x0/0xa0
Feb 26 08:26:32 moria kernel: [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
Feb 26 08:26:32 moria kernel: SPL: Dumping log to /tmp/spl-log.1361863592.29875

spl-log and more messages ('task blocked') at http://wwwlehre.dhbw-stuttgart.de/~bziller/spl-log.1361863592.29875.gz and http://wwwlehre.dhbw-stuttgart.de/~bziller/messages.1361863592.29875.gz

@ghost ghost reopened this Feb 26, 2013
@ryao
Copy link
Contributor

ryao commented Mar 3, 2013

I wrote a few posts over the course of thinking about this, so I decided consolidate my thoughts into a single post and delete any ideas that further thinking revealed to be obsolete.

@bziller This looks like a duplicate of openzfs/spl#157, which was determined to have been caused by memory corruption. Does your system use ECC memory? If not, I am going to guess that a corrupt pointer caused nonsense to be copied into the sa_magic field, which was then written to disk with a good checksum. You might be able to identify the bad file by watching rsync's behavior. It likely freezes on a given file, which would be the bad one.

@ahrens @behlendorf It might be best to handle this differently than we do now. If the magic number is invalid, we could invoke the failmode behavior. We could also implement a flag to zpool scrub will identify bad blocks that have valid checksums when there are redundant copies by doing a byte-by-byte comparison of the redundant data when checksums are valid to verify that the blocks are actually sane. If a comparison fails, but the majority of copies agree (e.g. 2/3), then we can do self healing. If we cannot get a majority, then the best we could do is to mark all copies as being bad. What are your thoughts about these ideas?

@ahrens
Copy link
Member

ahrens commented Mar 3, 2013

@ryao I think you are proposing two changes to the scrub code:

  1. Check that all ditto'ed copies of a block agree. Given that we already check that all copies of the block have the same, correct checksum, I'm inclined to simply trust the checksum algorithm here. I don't see a lot of benefit to trying to catch copies that are different but have the same checksum. If this is a realistic failure mode, I'd suggest using a stronger checksum algorithm (e.g. sha256).
  2. Do some semantic verification while scrubbing. This seems fine; there is quite a bit you can verify when examining each block independently (e.g. the magic numbers as you pointed out). I'd suggest that you build this into the zio pipeline so that this verification can (optionally) happen whenever we read a block, whether via scrub or the normal read path. You could have a per-object type callback like the byteswap callbacks.

@ghost
Copy link
Author

ghost commented Mar 4, 2013

@ryao The system has ECC. A 24h memtest86+ run didn't find any bad memory.

But basically this error means that I have bad data with a good checksum on disk?
What are the possible (easy) ways the fix this (besides restoring from backup)?
In openzfs/spl#157 (comment) behlendorf mentions disabling that VERIFY, deleting the offending file(s) and reenabling the VERIFY.
How should I disable this VERIFY?

@nedbass
Copy link
Contributor

nedbass commented Mar 5, 2013

It's interesting that in each reported instance of this bug, sa.sa_magic seems to contain a timestamp in seconds since the epoch.

See also https://groups.google.com/a/zfsonlinux.org/forum/?fromgroups=#!topic/zfs-discuss/Vp02RDQ2GjI

@nedbass
Copy link
Contributor

nedbass commented Mar 5, 2013

I wonder if this is related to #1240. In that bug, we found that sa_find_sizes() might incorrectly indicate that the a spill block won't be needed. Accordingly, the variable spillhdrsize is left set to zero in sa_build_layouts(). Now the following code from sa_build_layouts() handles the transition from a bonus to a spill buffer. Note that if spillhdrsize is zero then data_start points to the sahdr, and subsequent writes would corrupt the header, overwriting the sa_magic field.

 756                 if (buf_space < length) {  /* switch to spill buffer */
 757                         VERIFY(spilling);
 758                         VERIFY(bonustype == DMU_OT_SA);
 759                         if (buftype == SA_BONUS && !sa->sa_force_spill) {
 760                                 sa_find_layout(hdl->sa_os, hash, attrs_start,
 761                                     lot_count, tx, &lot);
 762                                 SA_SET_HDR(sahdr, lot->lot_num, hdrsize);
 763                         }
 764 
 765                         buftype = SA_SPILL;
 766                         hash = -1ULL;
 767                         len_idx = 0;
 768 
 769                         sahdr = (sa_hdr_phys_t *)hdl->sa_spill->db_data;
 770                         sahdr->sa_magic = SA_MAGIC;
 771                         data_start = (void *)((uintptr_t)sahdr +
 772                             spillhdrsize);
 773                         attrs_start = &attrs[i];
 774                         buf_space = hdl->sa_spill->db_size - spillhdrsize;
 775                         lot_count = 0;
 776                 }

@nedbass
Copy link
Contributor

nedbass commented Mar 5, 2013

On second thought I guess that theory doesn't hold up, since we panicked in that case. Also there's a SA_SET_HDR further down that would rewrite the header.

@jcea
Copy link

jcea commented Apr 5, 2013

I am hitting this too, also while doing a rsync.

Apr 5 21:33:54 csi kernel: [ 301.262394] VERIFY3(sa.sa_magic ==
0x2F505A) failed (1316101490 == 3100762)
Apr 5 21:33:54 csi kernel: [ 301.262797] SPLError:
2029:0:(zfs_vfsops.c:347:zfs_space_delta_cb()) SPL PANIC
Apr 5 21:33:54 csi kernel: [ 301.263175] SPL: Showing stack for
process 2029
Apr 5 21:33:54 csi kernel: [ 301.263179] Pid: 2029, comm: txg_sync
Tainted: P O 3.5.0-26-generic #42~precise1-Ubuntu
Apr 5 21:33:54 csi kernel: [ 301.263181] Call Trace:
Apr 5 21:33:54 csi kernel: [ 301.263201] []
spl_debug_dumpstack+0x27/0x40 [spl]
Apr 5 21:33:54 csi kernel: [ 301.263208] []
spl_debug_bug+0x82/0xe0 [spl]
Apr 5 21:33:54 csi kernel: [ 301.263249] []
zfs_space_delta_cb+0x18e/0x1a0 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263269] []
dmu_objset_userquota_get_ids+0xcf/0x420 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263276] [] ?
mutex_lock+0x1d/0x50
Apr 5 21:33:54 csi kernel: [ 301.263296] []
dnode_sync+0xa2/0xb30 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263314] [] ?
dbuf_sync_list+0x77/0xa0 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263318] [] ?
mutex_lock+0x1d/0x50
Apr 5 21:33:54 csi kernel: [ 301.263338] []
dmu_objset_sync_dnodes+0xbb/0xe0 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263357] []
dmu_objset_sync+0x18e/0x330 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263375] [] ?
secondary_cache_changed_cb+0x20/0x20 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263394] [] ?
dmu_objset_sync+0x330/0x330 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263415] []
dsl_dataset_sync+0x4c/0x60 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263437] []
dsl_pool_sync+0xc8/0x530 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263461] []
spa_sync+0x3a8/0xa50 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263491] []
txg_sync_thread+0x2df/0x540 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263516] [] ?
txg_init+0x250/0x250 [zfs]
Apr 5 21:33:54 csi kernel: [ 301.263525] []
thread_generic_wrapper+0x78/0x90 [spl]
Apr 5 21:33:54 csi kernel: [ 301.263531] [] ?
__thread_create+0x310/0x310 [spl]
Apr 5 21:33:54 csi kernel: [ 301.263537] []
kthread+0x93/0xa0
Apr 5 21:33:54 csi kernel: [ 301.263542] []
kernel_thread_helper+0x4/0x10
Apr 5 21:33:54 csi kernel: [ 301.263546] [] ?
flush_kthread_worker+0xb0/0xb0
Apr 5 21:33:54 csi kernel: [ 301.263550] [] ?
gs_change+0x13/0x13

@dward
Copy link

dward commented Oct 7, 2013

I just received this error during a mass delete:

Oct 6 02:42:02 master kernel: VERIFY3(sa.sa_magic == 0x2F505A) failed (1379523424 == 3100762)
Oct 6 02:42:02 master kernel: SPLError: 3835:0:(zfs_vfsops.c:347:zfs_space_delta_cb()) SPL PANIC
Oct 6 02:42:02 master kernel: SPL: Showing stack for process 3835
Oct 6 02:42:03 master kernel: Pid: 3835, comm: txg_sync Tainted: P 2.6.32-100.24.3.tn #1
Oct 6 02:42:03 master kernel: Call Trace:
Oct 6 02:42:03 master kernel: [] ? should_resched+0xe/0x2f
Oct 6 02:42:03 master kernel: [] zfs_space_delta_cb+0xea/0x24e [zfs]
Oct 6 02:42:03 master kernel: [] dmu_objset_userquota_get_ids+0x1a8/0x2ba [zfs]
Oct 6 02:42:03 master kernel: [] dnode_sync+0xab/0x7de [zfs]
Oct 6 02:42:03 master kernel: [] ? zrl_add+0x26/0x66 [zfs]
Oct 6 02:42:03 master kernel: [] spl_debug_bug+0x88/0xbf [spl]
Oct 6 02:42:03 master kernel: [] dmu_objset_sync_dnodes+0x62/0x7b [zfs]
Oct 6 02:42:03 master kernel: [] ? _cond_resched+0xe/0x22
Oct 6 02:42:03 master kernel: [] spl_debug_dumpstack+0x30/0x32 [spl]
Oct 6 02:42:03 master kernel: [] ? dmu_objset_write_ready+0x0/0x38 [zfs]
Oct 6 02:42:03 master kernel: [] dsl_pool_sync+0xb2/0x45d [zfs]
Oct 6 02:42:03 master kernel: [] dmu_objset_sync+0x25b/0x2d3 [zfs]
Oct 6 02:42:03 master kernel: [] ? need_resched+0x23/0x2d
Oct 6 02:42:03 master kernel: [] ? mutex_lock+0x16/0x3a
Oct 6 02:42:03 master kernel: [] ? arc_write_done+0x0/0x1e3 [zfs]
Oct 6 02:42:03 master kernel: [] txg_sync_thread+0x284/0x43f [zfs]
Oct 6 02:42:03 master kernel: [] ? need_resched+0x23/0x2d
Oct 6 02:42:03 master kernel: [] ? child_rip+0x0/0x20
Oct 6 02:42:03 master kernel: [] thread_generic_wrapper+0x61/0x6e [spl]
Oct 6 02:42:03 master kernel: [] ? should_resched+0xe/0x2f
Oct 6 02:42:03 master kernel: [] ? ktime_get_ts+0x89/0x92
Oct 6 02:42:03 master kernel: [] ? timekeeping_get_ns+0x1b/0x3d
Oct 6 02:42:03 master kernel: [] spa_sync+0x485/0x8ae [zfs]
Oct 6 02:42:03 master kernel: [] ? thread_generic_wrapper+0x0/0x6e [spl]
Oct 6 02:42:03 master kernel: [] dsl_dataset_sync+0x45/0x4d [zfs]
Oct 6 02:42:03 master kernel: [] child_rip+0xa/0x20
Oct 6 02:42:03 master kernel: [] ? kthread+0x0/0x76
Oct 6 02:42:03 master kernel: [] kthread+0x6e/0x76
Oct 6 02:42:03 master kernel: [] ? txg_sync_thread+0x0/0x43f [zfs]
Oct 6 02:42:03 master kernel: [] ? dmu_objset_write_done+0x0/0x57 [zfs]
Oct 6 02:42:03 master kernel: [] ? set_user_nice+0xed/0x109

Any idea on why sa.sa_magic is equal to a unix timestamp?

@Orfheo
Copy link

Orfheo commented Dec 5, 2013

Found these messages a couple of day ago on my machine, a stable Gentoo amd64 system, using zfs 0.6.2-1:

Nov 30 19:02:58 sher kernel: [85427.669302] VERIFY3(sa.sa_magic == 0x2F505A) failed (1381750087 == 3100762)
Nov 30 19:02:58 sher kernel: [85427.669306] VERIFY3(hdrsize >= sizeof (sa_hdr_phys_t)) failed (0 >= 8)

that seems related to this issue.

The system has "normal", non-ECC, memory and didn't panic after the messages.

I can't reproduce the problem: I scrubbed the pool after the message, without booting, and scrubbed again, after a reboot:. Result, in both cases, "No known data errors" and no new errors in the system logs.

The messages appeared just once and the number "1381750087" is again a reasonable timestamp, as the command "date --date='@1381750087'" reveal:: Mon Oct 14 13:28:07 CEST 2013.

Note the VERIFY messages timestamps are related to one of my system logins, while the asserted "1381750087, Mon Oct 14 13:28:07 CEST 2013" show the strange coincidence with the usual time of my system logouts. The bad blocks, if any, may have been in one of my home profile files?

Any idea?

@behlendorf
Copy link
Contributor

Possibly related to #1890.

@behlendorf
Copy link
Contributor

This is believe to be resolved. If anyone observed an instance of a 'zfs_space_delta_cb()) SPL PANIC' in 0.6.3 or newer please open a new issue.

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

No branches or pull requests

9 participants