ZFS kernel panics on OpenIndiana a9

Discussion:

Aneurin Price

2014-03-14 13:43:38 UTC

Hello everyone,

I have an OI system which has today had four^W five panics in a row,
and I'm hoping somebody might be able to help me investigate what's
going on. The information I have so far is pasted at the end of this
mail. This machine was upgraded from OIa8 to a9 on Wednesday, and at
the same time, I installed an l2arc. Since copying this information I
removed the cache device though, and it's just happened again, so I
*guess* it's probably not relevant. Next I'll try telling it to boot
into the old BE, just in case.

Can anyone give me any pointers on how to debug this further, or what
information might be useful, bearing in mind that this system now only
runs for a few minutes at a time?

Thanks for your time,
Nye
--
[13:25:47]***@openindiana:~$ grep -i panic /var/adm/messages
Mar 14 12:24:32 openindiana ^Mpanic[cpu1]/thread=ffffff002e26bc40:
Mar 14 12:31:26 openindiana savecore: [ID 570001 auth.error] reboot
after panic: BAD TRAP: type=e (#pf Page fault) rp=ffffff002e26b640
addr=408 occurred in module "zfs" due to a NULL pointer dereference
Mar 14 12:31:26 openindiana savecore: [ID 906182 auth.error] Panic
crashdump pending on dump device but dumpadm -n in effect; run
savecore(1M) manually to extract. Image UUID
6bc392ff-4b14-e595-d465-838f7e5ef5f3.
Mar 14 12:31:49 openindiana DESC: The system has rebooted after a
kernel panic. Refer to http://illumos.org/msg/SUNOS-8000-KL for more
information.
Mar 14 12:31:49 openindiana IMPACT: There may be some performance
impact while the panic is copied to the savecore directory. Disk
space usage by panics can be substantial.
Mar 14 12:31:49 openindiana Use 'fmdump -Vp -u
6bc392ff-4b14-e595-d465-838f7e5ef5f3' to view more panic detail.
Please refer to the knowledge article for additional information.
Mar 14 12:37:00 openindiana ^Mpanic[cpu6]/thread=ffffff002e131c40:
Mar 14 12:42:37 openindiana savecore: [ID 570001 auth.error] reboot
after panic: BAD TRAP: type=e (#pf Page fault) rp=ffffff002e130f00
addr=40 occurred in module "zfs" due to a NULL pointer dereference
Mar 14 12:42:38 openindiana savecore: [ID 786448 auth.error] Panic
crashdump pending on dump device but dumpadm -n in effect; run
savecore(1M) manually to extract. Image UUID
80249880-02ff-64c2-9632-99797216da0a.
Mar 14 12:42:50 openindiana DESC: The system has rebooted after a
kernel panic. Refer to http://illumos.org/msg/SUNOS-8000-KL for more
information.
Mar 14 12:42:50 openindiana IMPACT: There may be some performance
impact while the panic is copied to the savecore directory. Disk
space usage by panics can be substantial.
Mar 14 12:42:50 openindiana Use 'fmdump -Vp -u
80249880-02ff-64c2-9632-99797216da0a' to view more panic detail.
Please refer to the knowledge article for additional information.
Mar 14 13:07:29 openindiana ^Mpanic[cpu7]/thread=ffffff002f67ec40:
Mar 14 13:13:17 openindiana savecore: [ID 570001 auth.error] reboot
after panic: BAD TRAP: type=e (#pf Page fault) rp=ffffff002f67df00
addr=40 occurred in module "zfs" due to a NULL pointer dereference
Mar 14 13:13:18 openindiana savecore: [ID 738693 auth.error] Panic
crashdump pending on dump device but dumpadm -n in effect; run
savecore(1M) manually to extract. Image UUID
c9c783ba-268d-c503-b8e7-990cefd266ee.
Mar 14 13:13:31 openindiana DESC: The system has rebooted after a
kernel panic. Refer to http://illumos.org/msg/SUNOS-8000-KL for more
information.
Mar 14 13:13:31 openindiana IMPACT: There may be some performance
impact while the panic is copied to the savecore directory. Disk
space usage by panics can be substantial.
Mar 14 13:13:31 openindiana Use 'fmdump -Vp -u
c9c783ba-268d-c503-b8e7-990cefd266ee' to view more panic detail.
Please refer to the knowledge article for additional information.
Mar 14 13:18:15 openindiana ^Mpanic[cpu6]/thread=ffffff002e26bc40:
Mar 14 13:23:51 openindiana savecore: [ID 570001 auth.error] reboot
after panic: BAD TRAP: type=e (#pf Page fault) rp=ffffff002e26b640
addr=408 occurred in module "zfs" due to a NULL pointer dereference
Mar 14 13:23:52 openindiana savecore: [ID 338254 auth.error] Panic
crashdump pending on dump device but dumpadm -n in effect; run
savecore(1M) manually to extract. Image UUID
c8a94bad-1e9a-4b36-ab47-fc5ac363ada8.
Mar 14 13:24:04 openindiana DESC: The system has rebooted after a
kernel panic. Refer to http://illumos.org/msg/SUNOS-8000-KL for more
information.
Mar 14 13:24:04 openindiana IMPACT: There may be some performance
impact while the panic is copied to the savecore directory. Disk
space usage by panics can be substantial.
Mar 14 13:24:04 openindiana Use 'fmdump -Vp -u
c8a94bad-1e9a-4b36-ab47-fc5ac363ada8' to view more panic detail.
Please refer to the knowledge article for additional information.
[13:25:59]***@openindiana:~$ fmdump -Vp -u
c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
TIME UUID SUNW-MSG-ID
Mar 14 2014 13:24:04.456339000 c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
SUNOS-8000-KL

TIME CLASS ENA
Mar 14 13:23:52.9293 ireport.os.sunos.panic.dump_pending_on_device
0x0000000000000000

nvlist version: 0
version = 0x0
class = list.suspect
uuid = c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
code = SUNOS-8000-KL
diag-time = 1394803444 221917
de = fmd:///module/software-diagnosis
fault-list-sz = 0x1
fault-list = (array of embedded nvlists)
(start fault-list[0])
nvlist version: 0
version = 0x0
class = defect.sunos.kernel.panic
certainty = 0x64
asru =
sw:///:path=/var/crash/openindiana/.c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
resource =
sw:///:path=/var/crash/openindiana/.c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
savecore-succcess = 0
os-instance-uuid = c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
panicstr = BAD TRAP: type=e (#pf Page fault)
rp=ffffff002e26b640 addr=408 occurred in module "zfs" due to a NULL
pointer dereference
panicstack = unix:die+dd () | unix:trap+17db () |
unix:cmntrap+e6 () | zfs:dva_get_dsize_sync+5c () |
zfs:bp_get_dsize_sync+28 () | zfs:dsl_dataset_block_kill+4e () |
zfs:free_blocks+10d () | zfs:dnode_sync+21e () |
zfs:dmu_objset_sync_dnodes+80 () | zfs:dmu_objset_sync+1bd () |
zfs:dsl_dataset_sync+51 () | zfs:dsl_pool_sync+99 () |
zfs:spa_sync+373 () | zfs:txg_sync_thread+27b () | unix:thread_start+8
() |
crashtime = 1394803096
panic-time = 14 March 2014 13:18:16 GMT GMT
(end fault-list[0])

fault-status = 0x1
severity = Major
__ttl = 0x1
__tod = 0x532302f4 0x1b332e38

Dan McDonald

2014-03-14 14:06:43 UTC

Permalink

<SNIP!>

Your panic corresponds to this snippet of code from spa_misc.c: dva_get_dsize_sync():

1634 vdev_t *vd = vdev_lookup_top(spa, DVA_GET_VDEV(dva));
1635 dsize = (asize >> SPA_MINBLOCKSHIFT) * vd->vdev_deflate_ratio;

vdev_lookup_top() is returning NULL, but it's being dereferenced anyway.

Now as to WHY that is happening, that's a more interesting question.

You didn't mention what kind of pool you have apart from that you added, then removed, and l2arc. I've been running a9 on a test VM, but it's a single-disk rpool and that's it.

Sorry I don't have more to go on right now,
Dan

Aneurin Price

2014-03-14 15:17:38 UTC

Permalink

Post by Dan McDonald

<SNIP!>

1634 vdev_t *vd = vdev_lookup_top(spa, DVA_GET_VDEV(dva));
1635 dsize = (asize >> SPA_MINBLOCKSHIFT) * vd->vdev_deflate_ratio;
vdev_lookup_top() is returning NULL, but it's being dereferenced anyway.
Now as to WHY that is happening, that's a more interesting question.
You didn't mention what kind of pool you have apart from that you added, then removed, and l2arc. I've been running a9 on a test VM, but it's a single-disk rpool and that's it.

Thanks for taking a look. This pool consists of one pair of mirrored
disks. Having copied /var/adm/messages to another machine, I can see
that of the six panics logged, there are two different stack traces:

unix:die+dd ()
unix:trap+17db ()
unix:cmntrap+e6 ()
zfs:dva_get_dsize_sync+5c ()
zfs:bp_get_dsize_sync+28 ()
zfs:dsl_dataset_block_kill+4e ()
zfs:free_blocks+10d ()
zfs:dnode_sync+21e ()
zfs:dmu_objset_sync_dnodes+80 ()
zfs:dmu_objset_sync+1bd ()
zfs:dsl_dataset_sync+51 ()
zfs:dsl_pool_sync+99 ()
zfs:spa_sync+373 ()
zfs:txg_sync_thread+27b ()
unix:thread_start+8 ()

unix:die+dd ()
unix:trap+17db ()
unix:cmntrap+e6 ()
zfs:vdev_is_dead+c ()
zfs:vdev_readable+16 ()
zfs:vdev_mirror_child_select+61 ()
zfs:vdev_mirror_io_start+d5 ()
zfs:zio_vdev_io_start+20a ()
zfs:zio_execute+8d ()
zfs:zio_nowait+42 ()
zfs:arc_read+89a ()
zfs:traverse_prefetcher+10e ()
zfs:traverse_visitbp+170 ()
zfs:traverse_dnode+10f ()
zfs:traverse_visitbp+572 ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_dnode+8e ()
zfs:traverse_visitbp+299 ()
zfs:traverse_prefetch_thread+a9 ()
genunix:taskq_d_thread+b1 ()
unix:thread_start+8 ()

So far as I can see, these appear to be unrelated(?), but both cases
are attempts to dereference pointers that shouldn't ever be null, but
are. The most recent happened while running from the older boot
environment (and with the l2arc device removed), so I presume I'm
looking at some kind of pool corruption on-disk. I've not had any ECC
errors, and zpool status does not report anything untoward: should I
try a scrub? I ask because I have a vague recollection of a couple of
cases where the poster has been informed that scrubbing has perturbed
the pool such that some information that might have been useful is now
lost.

On the plus(ish) side, the majority of disk activity on this machine
comes from a Windows VM (using KVM), and with that disabled it
*appears* to be stable, so there is at least some chance of the scrub
running successfully, unless it hits the same problem itself.

Thanks,
Nye

(I have this horrible sinking feeling that I'm going to be spending my
weekend restoring from backups...)

Aneurin Price

2014-03-15 11:30:03 UTC

Permalink

Post by Aneurin Price
Thanks for taking a look. This pool consists of one pair of mirrored
disks. Having copied /var/adm/messages to another machine, I can see
unix:die+dd ()
unix:trap+17db ()
unix:cmntrap+e6 ()
zfs:dva_get_dsize_sync+5c ()
zfs:bp_get_dsize_sync+28 ()
zfs:dsl_dataset_block_kill+4e ()
zfs:free_blocks+10d ()
zfs:dnode_sync+21e ()
zfs:dmu_objset_sync_dnodes+80 ()
zfs:dmu_objset_sync+1bd ()
zfs:dsl_dataset_sync+51 ()
zfs:dsl_pool_sync+99 ()
zfs:spa_sync+373 ()
zfs:txg_sync_thread+27b ()
unix:thread_start+8 ()

Okay, so this is the trace from the first panic, and one subsequent
one (not the second). I can't yet see anything that's correlated with
the time these happened.

Post by Aneurin Price
unix:die+dd ()
unix:trap+17db ()
unix:cmntrap+e6 ()
zfs:vdev_is_dead+c ()
zfs:vdev_readable+16 ()
zfs:vdev_mirror_child_select+61 ()
zfs:vdev_mirror_io_start+d5 ()
zfs:zio_vdev_io_start+20a ()
zfs:zio_execute+8d ()
zfs:zio_nowait+42 ()
zfs:arc_read+89a ()
zfs:traverse_prefetcher+10e ()
zfs:traverse_visitbp+170 ()
zfs:traverse_dnode+10f ()
zfs:traverse_visitbp+572 ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_visitbp+7fb ()
zfs:traverse_dnode+8e ()
zfs:traverse_visitbp+299 ()
zfs:traverse_prefetch_thread+a9 ()
genunix:taskq_d_thread+b1 ()
unix:thread_start+8 ()

This one is the trace from every other panic. It happens consistently
whenever I try to send from one of my datasets, starting at the next
snapshot created *after* the first crash. So:
***@snapX - created 20 mins before first crash
***@snapY - created shortly after rebooting from first crash

Running 'zfs send ***@snapX' completes successfully. Running 'zfs
send ***@snapY' or 'zfs send -i @snapX ***@snapY' panics
consistently. This is the same if Y is replaced with any later
snapshot, and/or X with any earlier.
All of the data in this dataset appears to be fine - I've looped
through every single file, dd'ing the contents to /dev/null, without
complaint. No errors are reported by 'zfs status'.

My rough plan of action at this time is to clone the last working
snapshot, update the contents to mirror the current state of the
dataset, then promote the clone to take the place of the original. I
expect this will solve the ongoing problem, but that leaves me with
the first crash to understand, which seems to have corrupted the pool.
Both of the times that particular crash happened were while I still
had the l2arc in use, so I'm still suspicious of that device.

Investigations are ongoing...

George Wilson

2014-03-15 14:35:07 UTC

Permalink

Post by Aneurin Price

From the panic can you look at the blockpointer that is passed into
bp_get_dsize_sync(). It will be the first argument and you can dump that
out by doing:

<addr>::blkptr

Post by Aneurin Price
Okay, so this is the trace from the first panic, and one subsequent
one (not the second). I can't yet see anything that's correlated with
the time these happened.

Here you can do a similar thing by looking at the first argument for
zio_vdev_io_start() and dumping out the the blockpointer like this:

<addr>::print zio_t io_bp | ::blkptr

Can you paste the output of those two commands along with the output of
::spa -v?

Thanks,
George

Post by Aneurin Price
This one is the trace from every other panic. It happens consistently
whenever I try to send from one of my datasets, starting at the next
consistently. This is the same if Y is replaced with any later
snapshot, and/or X with any earlier.
All of the data in this dataset appears to be fine - I've looped
through every single file, dd'ing the contents to /dev/null, without
complaint. No errors are reported by 'zfs status'.
My rough plan of action at this time is to clone the last working
snapshot, update the contents to mirror the current state of the
dataset, then promote the clone to take the place of the original. I
expect this will solve the ongoing problem, but that leaves me with
the first crash to understand, which seems to have corrupted the pool.
Both of the times that particular crash happened were while I still
had the l2arc in use, so I'm still suspicious of that device.
Investigations are ongoing...
-------------------------------------------
illumos-zfs
Archives: https://www.listbox.com/member/archive/182191/=now
RSS Feed: https://www.listbox.com/member/archive/rss/182191/22008002-303f2ff4
Modify Your Subscription: https://www.listbox.com/member/?&
Powered by Listbox: http://www.listbox.com

Aneurin Price

2014-03-15 16:24:35 UTC

Permalink

Post by George Wilson

Post by Aneurin Price

From the panic can you look at the blockpointer that is passed into
bp_get_dsize_sync(). It will be the first argument and you can dump that out
<addr>::blkptr

Sadly, I don't have the core dump from the first panic. It turns out
that saving is not enabled by default on OI, and the dump device was
overwritten in short order.

Post by George Wilson

Post by Aneurin Price
Okay, so this is the trace from the first panic, and one subsequent
one (not the second). I can't yet see anything that's correlated with
the time these happened.

Here you can do a similar thing by looking at the first argument for
<addr>::print zio_t io_bp | ::blkptr
Can you paste the output of those two commands along with the output of
::spa -v?

Maybe this is some use by itself, even without the first block pointer.

Post by George Wilson
::stack

vdev_is_dead+0xc(0)
vdev_readable+0x16(0)
vdev_mirror_child_select+0x61(ffffff0767823a08)
vdev_mirror_io_start+0xd5(ffffff0767823a08)
zio_vdev_io_start+0x20a(ffffff0767823a08)
zio_execute+0x8d(ffffff0767823a08)
zio_nowait+0x42(ffffff0767823a08)
arc_read+0x89a(0, ffffff06f67f3040, ffffff072e277f80, 0, 0, 2)
traverse_prefetcher+0x10e(ffffff06f67f3040, 0, ffffff072e277f80,
ffffff002e2bc370, ffffff072e277e00, ffffff002e44e930)
traverse_visitbp+0x170(ffffff002e2bcb10, ffffff072e277e00,
ffffff072e277f80, ffffff002e2bc370)
traverse_dnode+0x10f(ffffff002e2bcb10, ffffff072e277e00, 59d2e7, 211c7)
traverse_visitbp+0x572(ffffff002e2bcb10, ffffff072b6f5000,
ffffff072a0d5700, ffffff002e2bc510)
traverse_visitbp+0x7fb(ffffff002e2bcb10, ffffff072b6f5000,
ffffff074792a080, ffffff002e2bc5e0)
traverse_visitbp+0x7fb(ffffff002e2bcb10, ffffff072b6f5000,
ffffff074962e000, ffffff002e2bc6b0)
traverse_visitbp+0x7fb(ffffff002e2bcb10, ffffff072b6f5000,
ffffff074962a000, ffffff002e2bc780)
traverse_visitbp+0x7fb(ffffff002e2bcb10, ffffff072b6f5000,
ffffff074ad96000, ffffff002e2bc850)
traverse_visitbp+0x7fb(ffffff002e2bcb10, ffffff072b6f5000,
ffffff0743ab6000, ffffff002e2bc920)
traverse_visitbp+0x7fb(ffffff002e2bcb10, ffffff072b6f5000,
ffffff072b6f5040, ffffff002e2bc9c0)
traverse_dnode+0x8e(ffffff002e2bcb10, ffffff072b6f5000, 59d2e7, 0)
traverse_visitbp+0x299(ffffff002e2bcb10, 0, ffffff06fcc1d880, ffffff002e2bcb60)
traverse_prefetch_thread+0xa9(ffffff002e44e950)
taskq_d_thread+0xb1(ffffff071ee87b28)
thread_start+8()

Post by George Wilson
ffffff0767823a08::print zio_t io_bp | ::blkptr

DVA[0]=<1179817:200000dde00:180000000>
DVA[1]=<2032127:20000111400:100000000>
DVA[2]=<2032127:200000e8a00:180000000>
[L0 POOL_PROPS] ON ? (255) BE contiguous unique triple
size=200L/18200P birth=5067276512395264L/101P fill=5067275442847744
cksum=1000006e5:1200a900c00000:200000221:21286

Post by George Wilson
::spa -v

ADDR STATE NAME
ffffff06f67f3040 ACTIVE rpool

ADDR STATE AUX DESCRIPTION
ffffff06fc12b800 HEALTHY - root
ffffff06fc12a800 HEALTHY - mirror
ffffff06fc12a000 HEALTHY - /dev/dsk/c2t5000C50040519F9Fd0s0
ffffff06fc12b000 HEALTHY - /dev/dsk/c2t5000C500404990ECd0s0

Thanks,
Nye

Aneurin Price

2014-04-03 20:23:51 UTC

Permalink

<snipping everything to start again>

This problem is absolutely baffling me.

I determined experimentally that the panic occurred when sending from
one particular dataset, starting from a particular snapshot. I first
tried cloning an older snapshot, and rsyncing the differences across -
the problem reappeared a week or so later.
On a different machine I then tried creating a new pool, and
send|receiving all my datasets, stopping the problem dataset before
the snapshot in question. This appeared to succeed, but when rsyncing
the differences over again I discovered that there were certain files
(or possibly directories) in the newly received version of that
dataset that would cause a panic when written to.
This surprised me, since I was expecting that the send|receive process
would clean or at least detect any filesystem errors - bearing in mind
that all of the *contents* of the dataset were perfectly accessible -
but being short on time I just destroyed that dataset (not the whole
new pool), created a replacement (on the same pool), and repopulated
it along these lines:

for each snapshot in source dataset:
rsync source snapshot contents to new dataset
create snapshot of new dataset with old snapshot name

Once again, this *appeared* to succeed, and successfully completed a
scrub, until after a day or two of use, some writes to that new
dataset started causing panics again.
At my wits' end at this point, I created a new pool, and I've been
repopulating every dataset on it using the rsync strategy, so it has
not received any data from the original damaged pool, or the second
one, except via rsync.
I haven't yet completed this process, but I've already had a couple of
panics. Initially I assumed this was because I was still using the
damaged pool(s), but the stack trace indicates it happened in an IO to
the *new* pool.

How can this possibly be happening?

Post by George Wilson
::stack

dva_get_dsize_sync+0x5c(ffffff0138da8580, ffffff016c7b5648)
bp_get_dsize_sync+0x28(ffffff0138da8580, ffffff016c7b5648)
dbuf_write_ready+0x61(ffffff016c7b54d8, ffffff013dffd058, ffffff01667654f8)
arc_write_ready+0x2c(ffffff016c7b54d8)
zio_ready+0x63(ffffff016c7b54d8)
zio_execute+0x8d(ffffff016c7b54d8)
taskq_thread+0x285(ffffff013b145c48)
thread_start+8()

Output of spa -v. Note the spa argument to dva_get_dsize_sync
corresponds to newdata.
(The one that can't be opened is because this machine doesn't have

Post by George Wilson
::spa -v

ADDR STATE NAME
ffffff013ccfb540 ACTIVE data

ADDR STATE AUX DESCRIPTION
ffffff013b0bc000 DEGRADED - root
ffffff013a4a8800 DEGRADED - mirror
ffffff013a917000 HEALTHY - /dev/dsk/c3t1d0s0
ffffff013a6b6000 CANT_OPEN BAD_LABEL /dev/dsk/c3t2d0s0
ffffff0138da8580 ACTIVE newdata

ffffff013a931800 HEALTHY - root
ffffff013a918000 HEALTHY - /dev/dsk/c3t3d0s0
ffffff013c6d4b00 ACTIVE openindiana-rpool

ffffff013a4be800 HEALTHY - root
ffffff013a728800 HEALTHY - /dev/dsk/c3t2d0s0
ffffff01383ffac0 ACTIVE rpool

ffffff01389a5000 HEALTHY - root
ffffff0138b4e800 HEALTHY - /dev/dsk/c3t0d0s0

Post by George Wilson
ffffff016c7b5648::print dva_t | ::blkptr

DVA[0]=<2032127:600000e8a00:186000000>
DVA[1]=<2032127:6000010da00:186000000>
DVA[2]=<1179819:60000104400:106000000>
Surely that can't possibly be right? As I understand it the first of
the three sections from each DVA should be less than the number of
vdevs in the pool. Are there any situations where 2032127 could be the
right value there?

Looking at ffffff016c7b54d8::print zio_t includes:
io_prop = {
zp_checksum = 7 (ZIO_CHECKSUM_FLETCHER_4)
zp_compress = 3 (ZIO_COMPRESS_LZJB)
zp_type = 0t44 (DMU_OT_SA)
zp_level = 0
zp_copies = 0x2
zp_dedup = 0 (0)
zp_dedup_verify = 0 (0)
zp_nopwrite = 0 (0)
}
Since all my datasets are set to lz4 and copies=1, I infer that this
is an attempt to write a metadata block, so I'm currently running "zdb
-L -c" on the pool on the extremely slim chance that it might detect
something awry.

Bearing in mind that this has been happening on two separate systems,
both with ECC memory and no errors reported, I can't help but feel
that there must be some ZFS bug at work here, but does anyone have any
idea how this problem seems to be able to propagate itself in this
way? Is it possible that running the machine with the broken pool
imported at the same time as the new pool is causing some memory
corruption that then gets written to the new pool? I can't see how it
would always hit the same dataset if that were the case.

Thanks for reading this far, and if anyone can shed any light on this
problem I'd be extremely grateful, as I'm pretty much exhausted by
this point.

Nye

Richard Yao

2014-03-14 14:08:18 UTC

Permalink

Someone else will need to advise you on how to get the line number of the NULL pointer dereference, but from what you have said, the following might be a cause:

https://www.illumos.org/issues/4088

One idea that follows from this is to try removing l2arc to see if the crashes stop. If they continue with l2arc removed, that is not it.

Post by Aneurin Price
Hello everyone,
I have an OI system which has today had four^W five panics in a row,
and I'm hoping somebody might be able to help me investigate what's
going on. The information I have so far is pasted at the end of this
mail. This machine was upgraded from OIa8 to a9 on Wednesday, and at
the same time, I installed an l2arc. Since copying this information I
removed the cache device though, and it's just happened again, so I
*guess* it's probably not relevant. Next I'll try telling it to boot
into the old BE, just in case.
Can anyone give me any pointers on how to debug this further, or what
information might be useful, bearing in mind that this system now only
runs for a few minutes at a time?
Thanks for your time,
Nye
--
Mar 14 12:31:26 openindiana savecore: [ID 570001 auth.error] reboot
after panic: BAD TRAP: type=e (#pf Page fault) rp=ffffff002e26b640
addr=408 occurred in module "zfs" due to a NULL pointer dereference
Mar 14 12:31:26 openindiana savecore: [ID 906182 auth.error] Panic
crashdump pending on dump device but dumpadm -n in effect; run
savecore(1M) manually to extract. Image UUID
6bc392ff-4b14-e595-d465-838f7e5ef5f3.
Mar 14 12:31:49 openindiana DESC: The system has rebooted after a
kernel panic. Refer to http://illumos.org/msg/SUNOS-8000-KL for more
information.
Mar 14 12:31:49 openindiana IMPACT: There may be some performance
impact while the panic is copied to the savecore directory. Disk
space usage by panics can be substantial.
Mar 14 12:31:49 openindiana Use 'fmdump -Vp -u
6bc392ff-4b14-e595-d465-838f7e5ef5f3' to view more panic detail.
Please refer to the knowledge article for additional information.
Mar 14 12:42:37 openindiana savecore: [ID 570001 auth.error] reboot
after panic: BAD TRAP: type=e (#pf Page fault) rp=ffffff002e130f00
addr=40 occurred in module "zfs" due to a NULL pointer dereference
Mar 14 12:42:38 openindiana savecore: [ID 786448 auth.error] Panic
crashdump pending on dump device but dumpadm -n in effect; run
savecore(1M) manually to extract. Image UUID
80249880-02ff-64c2-9632-99797216da0a.
Mar 14 12:42:50 openindiana DESC: The system has rebooted after a
kernel panic. Refer to http://illumos.org/msg/SUNOS-8000-KL for more
information.
Mar 14 12:42:50 openindiana IMPACT: There may be some performance
impact while the panic is copied to the savecore directory. Disk
space usage by panics can be substantial.
Mar 14 12:42:50 openindiana Use 'fmdump -Vp -u
80249880-02ff-64c2-9632-99797216da0a' to view more panic detail.
Please refer to the knowledge article for additional information.
Mar 14 13:13:17 openindiana savecore: [ID 570001 auth.error] reboot
after panic: BAD TRAP: type=e (#pf Page fault) rp=ffffff002f67df00
addr=40 occurred in module "zfs" due to a NULL pointer dereference
Mar 14 13:13:18 openindiana savecore: [ID 738693 auth.error] Panic
crashdump pending on dump device but dumpadm -n in effect; run
savecore(1M) manually to extract. Image UUID
c9c783ba-268d-c503-b8e7-990cefd266ee.
Mar 14 13:13:31 openindiana DESC: The system has rebooted after a
kernel panic. Refer to http://illumos.org/msg/SUNOS-8000-KL for more
information.
Mar 14 13:13:31 openindiana IMPACT: There may be some performance
impact while the panic is copied to the savecore directory. Disk
space usage by panics can be substantial.
Mar 14 13:13:31 openindiana Use 'fmdump -Vp -u
c9c783ba-268d-c503-b8e7-990cefd266ee' to view more panic detail.
Please refer to the knowledge article for additional information.
Mar 14 13:23:51 openindiana savecore: [ID 570001 auth.error] reboot
after panic: BAD TRAP: type=e (#pf Page fault) rp=ffffff002e26b640
addr=408 occurred in module "zfs" due to a NULL pointer dereference
Mar 14 13:23:52 openindiana savecore: [ID 338254 auth.error] Panic
crashdump pending on dump device but dumpadm -n in effect; run
savecore(1M) manually to extract. Image UUID
c8a94bad-1e9a-4b36-ab47-fc5ac363ada8.
Mar 14 13:24:04 openindiana DESC: The system has rebooted after a
kernel panic. Refer to http://illumos.org/msg/SUNOS-8000-KL for more
information.
Mar 14 13:24:04 openindiana IMPACT: There may be some performance
impact while the panic is copied to the savecore directory. Disk
space usage by panics can be substantial.
Mar 14 13:24:04 openindiana Use 'fmdump -Vp -u
c8a94bad-1e9a-4b36-ab47-fc5ac363ada8' to view more panic detail.
Please refer to the knowledge article for additional information.
c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
TIME UUID SUNW-MSG-ID
Mar 14 2014 13:24:04.456339000 c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
SUNOS-8000-KL
TIME CLASS ENA
Mar 14 13:23:52.9293 ireport.os.sunos.panic.dump_pending_on_device
0x0000000000000000
nvlist version: 0
version = 0x0
class = list.suspect
uuid = c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
code = SUNOS-8000-KL
diag-time = 1394803444 221917
de = fmd:///module/software-diagnosis
fault-list-sz = 0x1
fault-list = (array of embedded nvlists)
(start fault-list[0])
nvlist version: 0
version = 0x0
class = defect.sunos.kernel.panic
certainty = 0x64
asru =
sw:///:path=/var/crash/openindiana/.c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
resource =
sw:///:path=/var/crash/openindiana/.c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
savecore-succcess = 0
os-instance-uuid = c8a94bad-1e9a-4b36-ab47-fc5ac363ada8
panicstr = BAD TRAP: type=e (#pf Page fault)
rp=ffffff002e26b640 addr=408 occurred in module "zfs" due to a NULL
pointer dereference
panicstack = unix:die+dd () | unix:trap+17db () |
unix:cmntrap+e6 () | zfs:dva_get_dsize_sync+5c () |
zfs:bp_get_dsize_sync+28 () | zfs:dsl_dataset_block_kill+4e () |
zfs:free_blocks+10d () | zfs:dnode_sync+21e () |
zfs:dmu_objset_sync_dnodes+80 () | zfs:dmu_objset_sync+1bd () |
zfs:dsl_dataset_sync+51 () | zfs:dsl_pool_sync+99 () |
zfs:spa_sync+373 () | zfs:txg_sync_thread+27b () | unix:thread_start+8
() |
crashtime = 1394803096
panic-time = 14 March 2014 13:18:16 GMT GMT
(end fault-list[0])
fault-status = 0x1
severity = Major
__ttl = 0x1
__tod = 0x532302f4 0x1b332e38
-------------------------------------------
illumos-zfs
Archives: https://www.listbox.com/member/archive/182191/=now
RSS Feed: https://www.listbox.com/member/archive/rss/182191/24010604-91e32bd2
Modify Your Subscription: https://www.listbox.com/member/?&
Powered by Listbox: http://www.listbox.com

-------------------------------------------
illumos-zfs
Archives: https://www.listbox.com/member/archive/182191/=now
RSS Feed: https://www.listbox.com/member/archive/rss/182191/23047029-187a0c8d
Modify Your Subscription: https://www.listbox.com/member/?member_id=23047029&id_secret=23047029-2e85923f
Powered by Listbox: http://www.listbox.com