Odd panic "NULL bp->data in g_io_request(cmd=1)" out of ZFS in latest -current

From: Richard Todd <rmtodd_at_ichotolot.servalan.com>
Date: Wed, 27 May 2009 19:36:27 -0500
Updated my main -current box to the most recent sources last night, and early
this morning (about 3:30am, so probably in the middle of daily periodic 
time), got the following intersting panic.  As near as I can tell, the ZFS
zio system queued a request up to read a block with io_data NULL and later 
cheerfully translated that into a BIO_READ request from geom with bp->data
null; this obviously caused geom to complain that there was nowhere to put
the requested data.  



Unread portion of the kernel message buffer:
panic: NULL bp->data in g_io_request(cmd=1)
cpuid = 1
KDB: enter: panic
shared lockmgr zfs (zfs) r = 0 (0xffffff00056f37e8) locked _at_ /usr/src/sys/kern/vfs_lookup.c:492
shared lockmgr zfs (zfs) r = 0 (0xffffff00056f37e8) locked _at_ /usr/src/sys/kern/vfs_lookup.c:492
shared lockmgr zfs (zfs) r = 0 (0xffffff0007e6c308) locked _at_ /usr/src/sys/kern/vfs_subr.c:2101
exclusive lockmgr zfs (zfs) r = 0 (0xffffff001a13ccc8) locked _at_ /usr/src/sys/kern/vfs_vnops.c:590
shared lockmgr zfs (zfs) r = 0 (0xffffff0118100cc8) locked _at_ /usr/src/sys/kern/vfs_subr.c:2101
shared lockmgr zfs (zfs) r = 0 (0xffffff00056f37e8) locked _at_ /usr/src/sys/kern/vfs_lookup.c:492
exclusive sx so_rcv_sx (so_rcv_sx) r = 0 (0xffffff00c7149378) locked _at_ /usr/src/sys/kern/uipc_sockbuf.c:148
exclusive sx so_rcv_sx (so_rcv_sx) r = 0 (0xffffff00ad419b10) locked _at_ /usr/src/sys/kern/uipc_sockbuf.c:148
exclusive sx so_rcv_sx (so_rcv_sx) r = 0 (0xffffff00c7093d98) locked _at_ /usr/src/sys/kern/uipc_sockbuf.c:148
exclusive lockmgr zfs (zfs) r = 0 (0xffffff0007e967e8) locked _at_ /usr/src/sys/kern/vfs_subr.c:2101
exclusive lockmgr bufwait (bufwait) r = 0 (0xffffff80c03ab578) locked _at_ /usr/src/sys/vm/vm_pager.c:310
exclusive lockmgr zfs (zfs) r = 0 (0xffffff0009f657e8) locked _at_ /usr/src/sys/kern/vfs_vnops.c:590
exclusive sleep mutex zio_cache (UMA zone) r = 0 (0xffffff0005724c50) locked _at_ /usr/src/sys/vm/uma_core.c:2602

0xffffff00056f3750: tag zfs, type VDIR
    usecount 344, writecount 0, refcount 345 mountedhere 0
    flags (VV_ROOT)
    v_object 0xffffff0007e9c258 ref 0 pages 0
    lock type zfs: SHARED (count 3)
#0 0xffffffff8054aeca at __lockmgr_args+0x51a
#1 0xffffffff805dc869 at vop_stdlock+0x39
#2 0xffffffff8087e5db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805f8907 at _vn_lock+0x57
#4 0xffffffff805e0cf5 at lookup+0xf5
#5 0xffffffff805e2026 at namei+0x546
#6 0xffffffff805f0e8f at kern_statat_vnhook+0x8f
#7 0xffffffff805f1035 at kern_statat+0x15
#8 0xffffffff805f11da at stat+0x2a
#9 0xffffffff80835ac7 at syscall+0x1e7
#10 0xffffffff80810490 at Xfast_syscall+0xd0

0xffffff0007e6c270: tag zfs, type VDIR
    usecount 1, writecount 0, refcount 2 mountedhere 0
    flags ()
    v_object 0xffffff003471b960 ref 0 pages 0
    lock type zfs: SHARED (count 1)
#0 0xffffffff8054aeca at __lockmgr_args+0x51a
#1 0xffffffff805dc869 at vop_stdlock+0x39
#2 0xffffffff8087e5db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805f8907 at _vn_lock+0x57
#4 0xffffffff805ed21b at vget+0x8b
#5 0xffffffff805da350 at cache_lookup+0x4e0
#6 0xffffffff805da650 at vfs_cache_lookup+0xc0
#7 0xffffffff8087f4a7 at VOP_LOOKUP_APV+0xb7
#8 0xffffffff805e118b at lookup+0x58b
#9 0xffffffff805e2026 at namei+0x546
#10 0xffffffff805f0e8f at kern_statat_vnhook+0x8f
#11 0xffffffff805f1035 at kern_statat+0x15
#12 0xffffffff805f11da at stat+0x2a
#13 0xffffffff80835ac7 at syscall+0x1e7
#14 0xffffffff80810490 at Xfast_syscall+0xd0

0xffffff0007e96750: tag zfs, type VLNK
    usecount 0, writecount 0, refcount 4 mountedhere 0
    flags (VI_DOINGINACT)
    lock type zfs: EXCL by thread 0xffffff0005ae8720 (pid 1491)
#0 0xffffffff8054aeca at __lockmgr_args+0x51a
#1 0xffffffff805dc869 at vop_stdlock+0x39
#2 0xffffffff8087e5db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805f8907 at _vn_lock+0x57
#4 0xffffffff805ed21b at vget+0x8b
#5 0xffffffff805da350 at cache_lookup+0x4e0
#6 0xffffffff805da650 at vfs_cache_lookup+0xc0
#7 0xffffffff8087f4a7 at VOP_LOOKUP_APV+0xb7
#8 0xffffffff805e118b at lookup+0x58b
#9 0xffffffff805e2026 at namei+0x546
#10 0xffffffff805f0e8f at kern_statat_vnhook+0x8f
#11 0xffffffff805f1035 at kern_statat+0x15
#12 0xffffffff805f11da at stat+0x2a
#13 0xffffffff80835ac7 at syscall+0x1e7
#14 0xffffffff80810490 at Xfast_syscall+0xd0

0xffffff0009f65750: tag zfs, type VREG
    usecount 1, writecount 1, refcount 1 mountedhere 0
    flags ()
    v_object 0xffffff00094b0190 ref 0 pages 0
    lock type zfs: EXCL by thread 0xffffff0009038390 (pid 1355)
#0 0xffffffff8054b108 at __lockmgr_args+0x758
#1 0xffffffff805dc869 at vop_stdlock+0x39
#2 0xffffffff8087e5db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805f8907 at _vn_lock+0x57
#4 0xffffffff805f9c49 at vn_write+0x139
#5 0xffffffff805a47e5 at dofilewrite+0x85
#6 0xffffffff805a5db0 at kern_writev+0x60
#7 0xffffffff805a5e31 at writev+0x41
#8 0xffffffff80835ac7 at syscall+0x1e7
#9 0xffffffff80810490 at Xfast_syscall+0xd0

0xffffff001a13cc30: tag zfs, type VREG
    usecount 2, writecount 1, refcount 2 mountedhere 0
    flags ()
    v_object 0xffffff00c7e490c8 ref 0 pages 0
    lock type zfs: EXCL by thread 0xffffff000c173000 (pid 4819)
#0 0xffffffff8054b108 at __lockmgr_args+0x758
#1 0xffffffff805dc869 at vop_stdlock+0x39
#2 0xffffffff8087e5db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805f8907 at _vn_lock+0x57
#4 0xffffffff805f9c49 at vn_write+0x139
#5 0xffffffff805a47e5 at dofilewrite+0x85
#6 0xffffffff805a5db0 at kern_writev+0x60
#7 0xffffffff805a5eb4 at write+0x54
#8 0xffffffff80835ac7 at syscall+0x1e7
#9 0xffffffff80810490 at Xfast_syscall+0xd0

0xffffff0118100c30: tag zfs, type VREG
    usecount 4, writecount 0, refcount 5 mountedhere 0
    flags ()
    v_object 0xffffff0109184bb8 ref 3 pages 315
    lock type zfs: SHARED (count 1)
#0 0xffffffff8054aeca at __lockmgr_args+0x51a
#1 0xffffffff805dc869 at vop_stdlock+0x39
#2 0xffffffff8087e5db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805f8907 at _vn_lock+0x57
#4 0xffffffff805ed21b at vget+0x8b
#5 0xffffffff8078bedd at vm_fault+0xb5d
#6 0xffffffff808357c8 at trap_pfault+0x128
#7 0xffffffff80836454 at trap+0x504
#8 0xffffffff80810203 at calltrap+0x8
Physical memory: 4012 MB
Dumping 2266 MB: 2251 2235 2219 2203 2187 2171 2155 2139 2123 2107 2091 2075 2059 2043 2027 2011 1995 1979 1963 1947 1931 1915 1899 1883 1867 1851 1835 1819 1803 1787 1771 1755 1739 1723 1707 1691 1675 1659 1643 1627 1611 1595 1579 1563 1547 1531 1515 1499 1483 1467 1451 1435 1419 1403 1387 1371 1355 1339 1323 1307 1291 1275 1259 1243 1227 1211 1195 1179 1163 1147 1131 1115 1099 1083 1067 1051 1035 1019 1003 987 971 955 939 923 907 891 875 859 843 827 811 795 779 763 747 731 715 699 683 667 651 635 619 603 587 571 555 539 523 507 491 475 459 443 427 411 395 379 363 347 331 315 299 283 267 251 235 219 203 187 171 155 139 123 107 91 75 59 43 27 11

Reading symbols from /boot/kernel/zfs.ko...done.
Loaded symbols for /boot/kernel/zfs.ko
Reading symbols from /boot/kernel/opensolaris.ko...done.
Loaded symbols for /boot/kernel/opensolaris.ko
Reading symbols from /boot/kernel/geom_mirror.ko...done.
Loaded symbols for /boot/kernel/geom_mirror.ko
Reading symbols from /boot/kernel/snd_hda.ko...done.
Loaded symbols for /boot/kernel/snd_hda.ko
Reading symbols from /boot/kernel/sound.ko...done.
Loaded symbols for /boot/kernel/sound.ko
Reading symbols from /boot/kernel/coretemp.ko...done.
Loaded symbols for /boot/kernel/coretemp.ko
Reading symbols from /boot/kernel/atapicam.ko...done.
Loaded symbols for /boot/kernel/atapicam.ko
Reading symbols from /boot/kernel/tmpfs.ko...done.
Loaded symbols for /boot/kernel/tmpfs.ko
Reading symbols from /boot/kernel/linux.ko...done.
Loaded symbols for /boot/kernel/linux.ko
Reading symbols from /usr/local/modules/fuse.ko...done.
Loaded symbols for /usr/local/modules/fuse.ko
Reading symbols from /boot/kernel/green_saver.ko...done.
Loaded symbols for /boot/kernel/green_saver.ko
Reading symbols from /boot/kernel/radeon.ko...done.
Loaded symbols for /boot/kernel/radeon.ko
Reading symbols from /boot/kernel/drm.ko...done.
Loaded symbols for /boot/kernel/drm.ko
#0  doadump () at pcpu.h:223
223     pcpu.h: No such file or directory.
        in pcpu.h
(kgdb) bt
#0  doadump () at pcpu.h:223
#1  0xffffffff801cb48c in db_fncall (dummy1=Variable "dummy1" is not available.
)
    at /usr/src/sys/ddb/db_command.c:548
#2  0xffffffff801cb73d in db_command (last_cmdp=0xffffffff80bb8420, cmd_table=Variable "cmd_table" is not available.
)
    at /usr/src/sys/ddb/db_command.c:445
#3  0xffffffff801cff33 in db_script_exec (
    scriptname=0xffffff80ed1ff540 "kdb.enter.panic", warnifnotfound=0)
    at /usr/src/sys/ddb/db_script.c:302
#4  0xffffffff801d0002 in db_script_kdbenter (eventname=Variable "eventname" is not available.
)
    at /usr/src/sys/ddb/db_script.c:324
#5  0xffffffff801cd9b4 in db_trap (type=Variable "type" is not available.
) at /usr/src/sys/ddb/db_main.c:228
#6  0xffffffff80590075 in kdb_trap (type=3, code=0, tf=0xffffff80ed1ff760)
    at /usr/src/sys/kern/subr_kdb.c:534
#7  0xffffffff80836101 in trap (frame=0xffffff80ed1ff760)
    at /usr/src/sys/amd64/amd64/trap.c:613
#8  0xffffffff80810203 in calltrap ()
    at /usr/src/sys/amd64/amd64/exception.S:223
#9  0xffffffff8059024d in kdb_enter (why=0xffffffff8093b909 "panic", 
    msg=0xa <Address 0xa out of bounds>) at cpufunc.h:63
#10 0xffffffff8056088b in panic (fmt=Variable "fmt" is not available.
) at /usr/src/sys/kern/kern_shutdown.c:559
#11 0xffffffff80507e1f in g_io_request (bp=0xffffff002f804e10, 
    cp=0xffffff0005913580) at /usr/src/sys/geom/geom_io.c:347
#12 0xffffffff81045c44 in vdev_geom_io_start (zio=0xffffff0006ecb870)
    at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c:653
#13 0xffffffff81025987 in zio_execute (zio=0xffffff0006ecb870)
    at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zio.c:1085
#14 0xffffffff81014810 in vdev_mirror_io_start (zio=0xffffff0006ecb2d0)
    at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_mirror.c:303
#15 0xffffffff81025987 in zio_execute (zio=0xffffff0006ecb2d0)
    at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zio.c:1085
#16 0xffffffff81014810 in vdev_mirror_io_start (zio=0xffffff00a07b8b40)
    at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_mirror.c:303
#17 0xffffffff81025987 in zio_execute (zio=0xffffff00a07b8b40)
    at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zio.c:1085
#18 0xffffffff80fc9fb1 in taskq_thread (arg=Variable "arg" is not available.
)
    at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/os/taskq.c:854
#19 0xffffffff8053be8a in fork_exit (
    callout=0xffffffff80fc9de0 <taskq_thread>, arg=0xffffff00029bf240, 
    frame=0xffffff80ed1ffc90) at /usr/src/sys/kern/kern_fork.c:830
#20 0xffffffff8081068e in fork_trampoline ()
    at /usr/src/sys/amd64/amd64/exception.S:552
---Type <return> to continue, or q <return> to quit---
#21 0x0000000000000000 in ?? ()
#22 0x0000000000000000 in ?? ()
#23 0x0000000000000001 in ?? ()
#24 0x0000000000000000 in ?? ()
#25 0x0000000000000000 in ?? ()
#26 0x0000000000000000 in ?? ()
#27 0x0000000000000000 in ?? ()
#28 0x0000000000000000 in ?? ()
#29 0x0000000000000000 in ?? ()
#30 0x0000000000000000 in ?? ()
#31 0x0000000000000000 in ?? ()
#32 0x0000000000000000 in ?? ()
#33 0x0000000000000000 in ?? ()
#34 0x0000000000000000 in ?? ()
#35 0x0000000000000000 in ?? ()
#36 0x0000000000000000 in ?? ()
#37 0x0000000000000000 in ?? ()
#38 0x0000000000000000 in ?? ()
#39 0x0000000000000000 in ?? ()
#40 0x0000000000000000 in ?? ()
#41 0x0000000000000000 in ?? ()
#42 0x0000000000000000 in ?? ()
#43 0x0000000000000000 in ?? ()
#44 0x0000000000000000 in ?? ()
#45 0x000000000124b000 in ?? ()
#46 0x0000000000000000 in ?? ()
#47 0xffffffff80c0f358 in sleepq_chains ()
#48 0xffffffff80bf3f80 in affinity ()
#49 0xffffff0002897390 in ?? ()
#50 0xffffff80ed1ffa50 in ?? ()
#51 0xffffff80ed1ffa08 in ?? ()
#52 0xffffff000593b390 in ?? ()
#53 0xffffffff80583660 in sched_switch (td=0xffffff00029bf240, 
    newtd=0xffffffff80fc9de0, flags=Variable "flags" is not available.
) at /usr/src/sys/kern/sched_ule.c:1862
Previous frame inner to this frame (corrupt stack?)
(kgdb) fr 11
#11 0xffffffff80507e1f in g_io_request (bp=0xffffff002f804e10, 
    cp=0xffffff0005913580) at /usr/src/sys/geom/geom_io.c:347
347                     KASSERT(bp->bio_data != NULL,
(kgdb) l
342             bp->_bio_caller2 = bp->bio_caller2;
343             bp->_bio_cflags = bp->bio_cflags;
344     #endif
345     
346             if (bp->bio_cmd & (BIO_READ|BIO_WRITE|BIO_GETATTR)) {
347                     KASSERT(bp->bio_data != NULL,
348                         ("NULL bp->data in g_io_request(cmd=%hhu)", bp->bio_cmd));
349             }
350             if (bp->bio_cmd & (BIO_DELETE|BIO_FLUSH)) {
351                     KASSERT(bp->bio_data == NULL,
(kgdb) fr 12     
352                         ("non-NULL bp->data in g_io_request(cmd=%hhu)",
353                         bp->bio_cmd));
354             }
355             if (bp->bio_cmd & (BIO_READ|BIO_WRITE|BIO_DELETE)) {
356                     KASSERT(bp->bio_offset % cp->provider->sectorsize == 0,
357                         ("wrong offset %jd for sectorsize %u",
358                         bp->bio_offset, cp->provider->sectorsize));
359                     KASSERT(bp->bio_length % cp->provider->sectorsize == 0,
360                         ("wrong length %jd for sectorsize %u",
361                         bp->bio_length, cp->provider->sectorsize));
(kgdb) p bp
$1 = (struct bio *) 0xffffff002f804e10
(kgdb) p *bp
$2 = {bio_cmd = 1 '\001', bio_flags = 0 '\0', bio_cflags = 0 '\0', 
  bio_pflags = 0 '\0', bio_dev = 0x0, bio_disk = 0x0, bio_offset = 9495077376, 
  bio_bcount = 0, bio_data = 0x0, bio_error = 0, bio_resid = 0, 
  bio_done = 0xffffffff81045d40 <vdev_geom_io_intr>, bio_driver1 = 0x0, 
  bio_driver2 = 0x0, bio_caller1 = 0xffffff0006ecb870, bio_caller2 = 0x0, 
  bio_queue = {tqe_next = 0x0, tqe_prev = 0x0}, bio_attribute = 0x0, 
  bio_from = 0x0, bio_to = 0x0, bio_length = 14848, bio_completed = 0, 
  bio_children = 0, bio_inbed = 0, bio_parent = 0x0, bio_t0 = {sec = 0, 
    frac = 0}, bio_task = 0, bio_task_arg = 0x0, 
  _bio_caller1 = 0xffffff0006ecb870, _bio_caller2 = 0x0, _bio_cflags = 0 '\0', 
  bio_pblkno = 0}
(kgdb) fr 12
#12 0xffffffff81045c44 in vdev_geom_io_start (zio=0xffffff0006ecb870)
    at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/vdev_geom.c:653
653             g_io_request(bp, cp);
(kgdb) p *zio
$3 = {io_bookmark = {zb_objset = 47, zb_object = 812224, zb_level = 0, 
    zb_blkid = 1}, io_prop = {zp_checksum = ZIO_CHECKSUM_INHERIT, 
    zp_compress = ZIO_COMPRESS_INHERIT, zp_type = DMU_OT_NONE, 
    zp_level = 0 '\0', zp_ndvas = 0 '\0'}, io_type = ZIO_TYPE_READ, 
  io_child_type = ZIO_CHILD_VDEV, io_cmd = 0, io_priority = 0 '\0', 
  io_reexecute = 0 '\0', io_async_root = 0 '\0', io_txg = 338656806, 
  io_spa = 0xffffff0005773000, io_bp = 0xffffff0006ecb8c8, io_bp_copy = {
    blk_dva = {{dva_word = {29, 18536881}}, {dva_word = {0, 0}}, {dva_word = {
          0, 0}}}, blk_prop = 9223378642516312092, blk_pad = {0, 0, 0}, 
    blk_birth = 338656806, blk_fill = 0, blk_cksum = {zc_word = {
        4121883143947992538, 2241231356647247877, 10499032108141833196, 
        18092516276412224804}}}, io_parent = 0xffffff0006ecb2d0, 
  io_child = 0x0, io_sibling_prev = 0x0, io_sibling_next = 0x0, 
  io_logical = 0xffffff00681a62d0, io_transform_stack = 0x0, io_ready = 0, 
  io_done = 0xffffffff81014220 <vdev_mirror_child_done>, 
  io_private = 0xffffff001f40b8a8, io_bp_orig = {blk_dva = {{dva_word = {29, 
          18536881}}, {dva_word = {0, 0}}, {dva_word = {0, 0}}}, 
    blk_prop = 9223378642516312092, blk_pad = {0, 0, 0}, 
    blk_birth = 338656806, blk_fill = 0, blk_cksum = {zc_word = {
        4121883143947992538, 2241231356647247877, 10499032108141833196, 
        18092516276412224804}}}, io_data = 0x0, io_size = 14848, 
  io_vd = 0xffffff0005941800, io_vsd = 0x0, io_vsd_free = 0, 
  io_offset = 9495077376, io_deadline = 9795, io_offset_node = {avl_child = {
      0x0, 0x0}, avl_pcb = 1}, io_deadline_node = {avl_child = {0x0, 0x0}, 
    avl_pcb = 1}, io_vdev_tree = 0xffffff0005941c48, io_delegate_list = 0x0, 
  io_delegate_next = 0x0, io_flags = 177, io_stage = ZIO_STAGE_VDEV_IO_START, 
  io_pipeline = 63488, io_orig_flags = 145, io_orig_stage = ZIO_STAGE_READY, 
  io_orig_pipeline = 63488, io_error = 0, io_child_error = {0, 0, 0}, 
  io_children = {{0, 0}, {0, 0}, {0, 0}}, io_stall = 0x0, io_gang_tree = 0x0, 
  io_executor = 0xffffff000593b390, io_waiter = 0x0, io_lock = {lock_object = {
      lo_name = 0xffffffff810a0407 "zio->io_lock", lo_flags = 41484304, 
      lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, io_cv = {
    cv_description = 0xffffffff810a0432 "zio->io_cv)", cv_waiters = 0}, 
  io_ena = 0}
(kgdb) q
ichotolot# exit
Received on Wed May 27 2009 - 22:49:08 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:39:48 UTC