7.3-S amd64 - ZFS replace/attach hangs - related to 'guid mismatch' / GEOM?

Karl Pielorz kpielorz_lst at tdx.co.uk
Mon Jul 5 19:06:04 UTC 2010


Hi,

A previously working system (amd64, 10Gb of RAM, two dual core Opteron 285's
 - stock GENERIC kernel) - where I've done 'zpool attach' and 'zpool 
replace's
before (admittedly under 7.2-S) hangs when doing either of those now.

If I run:

host# zpool attach vol ad34 ad40

ZFS debugging shows:

"
vdev_geom_attach:112[1]: Attaching to ad40.
vdev_geom_attach:153[1]: Created consumer for ad40.
vdev_geom_read_guid:334[1]: guid for ad40 is 13247785578180267154
vdev_geom_detach:173[1]: Closing access to ad40.
vdev_geom_detach:177[1]: Destroyed consumer to ad40.
vdev_geom_open_by_path:472[1]: guid mismatch for provider /dev/ad40: 
835553262974889329 != 13247785578180267154.
vdev_geom_open_by_guid:430[1]: Searching by guid [835553262974889329].
"

And that's it.

'ps axl' shows the zpool process as:

"
 0  2250  2004   0  -8  0 14460  2044 g_wait D+    p0    0:00.01 zpool 
attach vol ad34 ad40
"

So it appears to be hung in 'g_wait'.

I re-ran the replace, but with GEOM and ZFS debug enabled - the rather large
output is below.

I'm concerned about "guid mismatch for provider /dev/ad40: 
835553262974889329
!= 13247785578180267154." - and then the fact the GEOM seems to start to
enumerate all the disk devices it can, and something hangs while it's 
looking at
"zvol/vol/scanned at 1237495449"?

'zvol/vol/scanned at 1237495449' is a snapshot of a zfs volume (not FS), which 
is encrypted using
GELI (but not currently geli attached, nor mounted).

Any advice?

Thanks,

-Karl


Zpool status output:

host# zpool status
  pool: vol
 state: ONLINE
 scrub: none requested
config:

        NAME        STATE     READ WRITE CKSUM
        vol         ONLINE       0     0     0
          mirror    ONLINE       0     0     0
            ad28    ONLINE       0     0     0
            ad12    ONLINE       0     0     0
          mirror    ONLINE       0     0     0
            ad14    ONLINE       0     0     0
            ad30    ONLINE       0     0     0
          mirror    ONLINE       0     0     0
            ad16    ONLINE       0     0     0
            ad32    ONLINE       0     0     0
          mirror    ONLINE       0     0     0
            ad18    ONLINE       0     0     0
            ad34    ONLINE       0     0     0
          mirror    ONLINE       0     0     0
            ad20    ONLINE       0     0     0
            ad36    ONLINE       0     0     0
          mirror    ONLINE       0     0     0
            ad22    ONLINE       0     0     0
            ad38    ONLINE       0     0     0
        spares
          ad42      AVAIL

(ad40 was also previously a spare - but I did a 'zpool remove vol ad40' to 
free it up)



Attempting the attach again, but with GEOM and ZFS debug enabled:

host# zpool attach vol ad34 ad40

Jul  5 19:42:50 host kernel: g_dev_open(ad40, 1, 8192, 0xffffff000e655ae0)
Jul  5 19:42:50 host kernel: g_access(0xffffff0004b20280(ad40), 1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, 1, 0, 0)
Jul  5 19:42:50 host kernel: g_dev_close(ad40, 1, 8192, 0xffffff000e655ae0)
Jul  5 19:42:50 host kernel: g_access(0xffffff0004b20280(ad40), -1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, -1, 0, 0)
Jul  5 19:42:50 host kernel: g_dev_open(ad40, 1, 8192, 0xffffff000e655ae0)
Jul  5 19:42:50 host kernel: g_access(0xffffff0004b20280(ad40), 1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, 1, 0, 0)
Jul  5 19:42:50 host kernel: g_dev_close(ad40, 1, 8192, 0xffffff000e655ae0)
Jul  5 19:42:50 host kernel: g_access(0xffffff0004b20280(ad40), -1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, -1, 0, 0)
Jul  5 19:42:50 host kernel: g_dev_open(ad40, 1, 8192, 0xffffff000e655ae0)
Jul  5 19:42:50 host kernel: g_access(0xffffff0004b20280(ad40), 1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, 1, 0, 0)
Jul  5 19:42:50 host kernel: g_dev_close(ad40, 1, 8192, 0xffffff000e655ae0)
Jul  5 19:42:50 host kernel: g_access(0xffffff0004b20280(ad40), -1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, -1, 0, 0)
Jul  5 19:42:50 host kernel: g_dev_open(ad40, 1, 8192, 0xffffff000e655ae0)
Jul  5 19:42:50 host kernel: g_access(0xffffff0004b20280(ad40), 1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, 1, 0, 0)
Jul  5 19:42:50 host kernel: g_dev_close(ad40, 1, 8192, 0xffffff000e655ae0)
Jul  5 19:42:50 host kernel: g_access(0xffffff0004b20280(ad40), -1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, -1, 0, 0)
Jul  5 19:42:50 host kernel: vdev_geom_open_by_path:461[1]: Found provider 
by name /dev/ad40.
Jul  5 19:42:50 host kernel: vdev_geom_attach:112[1]: Attaching to ad40.
Jul  5 19:42:50 host kernel: g_access(0xffffff00351c1480(ad40), 1, 1, 1)
Jul  5 19:42:50 host kernel: open delta:[r1w1e1] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, 1, 1, 1)
Jul  5 19:42:50 host kernel: g_post_event_x(0xffffffff802557e0, 
0xffffff0004ae2500, 2, 0)
Jul  5 19:42:50 host kernel: ref 0xffffff0004ae2500
Jul  5 19:42:50 host kernel: vdev_geom_attach:153[1]: Created consumer for 
ad40.
Jul  5 19:42:50 host kernel: vdev_geom_read_guid:334[1]: guid for ad40 is 
13247785578180267154
Jul  5 19:42:50 host kernel: vdev_geom_detach:173[1]: Closing access to 
ad40.
Jul  5 19:42:50 host kernel: g_access(0xffffff00351c1480(ad40), -1, 0, -1)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e-1] old:[r1w1e1] 
provider:[r1w1e1] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, -1, 0, -1)
Jul  5 19:42:50 host kernel: vdev_geom_detach:177[1]: Destroyed consumer to 
ad40.
Jul  5 19:42:50 host kernel: g_access(0xffffff00351c1480(ad40), 0, -1, 0)
Jul  5 19:42:50 host kernel: open delta:[r0w-1e0] old:[r0w1e0] 
provider:[r0w1e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, 0, -1, 0)
Jul  5 19:42:50 host kernel: g_post_event_x(0xffffffff80255580, 
0xffffff0004ae2500, 2, 0)
Jul  5 19:42:50 host kernel: ref 0xffffff0004ae2500
Jul  5 19:42:50 host kernel: g_detach(0xffffff00351c1480)
Jul  5 19:42:50 host kernel: g_destroy_consumer(0xffffff00351c1480)
Jul  5 19:42:50 host kernel: vdev_geom_open_by_path:472[1]: guid mismatch 
for provider /dev/ad40: 6262509414735727538 != 13247785578180267154.
Jul  5 19:42:50 host kernel: 
vgd_epva_rgte_otma_sotpee(nP_AbRyT_,gaudi4d0:)43
Jul  5 19:42:50 host kernel: 0[1]: Seagr_cahcicnegs sb(y0 xgfufifdf 
f[f0602365215c009340104(7a3d54702)7,5 381],. 0,
Jul  5 19:42:50 host kernel: g_0p)os
Jul  5 19:42:50 host kernel: to_peevne ndte_lxt(a0:x[frf1fwf0fef0f]f 
8o0l8da:8[4re00w, 0e00x]f fpfrfofvfi0de0r0:1[arc09w700e00,]  2,0 
xf2f6f2f1f4f40)0
Jul  5 19:42:50 host kernel: 04ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, 1, 0, 0)
Jul  5 19:42:50 host kernel: g_access(0xffffff00351c0300(ad40), -1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, -1, 0, 0)
Jul  5 19:42:50 host kernel: g_wither_geom(0xffffff000eda9800(ad40))
Jul  5 19:42:50 host kernel: bsd_taste(BSD,ad40)
Jul  5 19:42:50 host kernel: g_access(0xffffff003517b880(ad40), 1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, 1, 0, 0)
Jul  5 19:42:50 host kernel: g_access(0xffffff003517b880(ad40), -1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, -1, 0, 0)
Jul  5 19:42:50 host kernel: g_slice_spoiled(0xffffff003517b880/ad40)
Jul  5 19:42:50 host kernel: g_wither_geom(0xffffff003527c100(ad40))
Jul  5 19:42:50 host kernel: g_label_taste(LABEL, ad40)
Jul  5 19:42:50 host kernel: g_access(0xffffff003517aa00(ad40), 1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, 1, 0, 0)
Jul  5 19:42:50 host kernel: g_access(0xffffff003517aa00(ad40), -1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, -1, 0, 0)
Jul  5 19:42:50 host kernel: g_detach(0xffffff003517aa00)
Jul  5 19:42:50 host kernel: g_destroy_consumer(0xffffff003517aa00)
Jul  5 19:42:50 host kernel: g_destroy_geom(0xffffff000ee56500(label:taste))
Jul  5 19:42:50 host kernel: mbr_taste(MBR,ad40)
Jul  5 19:42:50 host kernel: g_access(0xffffff000ef8c580(ad40), 1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, 1, 0, 0)
Jul  5 19:42:50 host kernel: g_access(0xffffff000ef8c580(ad40), -1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 0xffffff0004ae2500(ad40)
Jul  5 19:42:50 host kernel: g_disk_access(ad40, -1, 0, 0)
Jul  5 19:42:50 host kernel: g_slice_spoiled(0xffffff000ef8c580/ad40)
Jul  5 19:42:50 host kernel: g_wither_geom(0xffffff0035909b00(ad40))
Jul  5 19:42:50 host kernel: g_mbrext_taste(MBREXT,ad40)
Jul  5 19:42:50 host kernel: g_eli_taste(ELI, ad40)
Jul  5 19:42:50 host kernel: 
g_access(0xffffff0035015380(zvol/vol2/zfs_backups/secure at 1243935776), 1, 0, 
0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 
0xffffff000e832000(zvol/vol2/zfs_backups/secure at 1243935776)
Jul  5 19:42:50 host kernel: 
g_access(0xffffff0035015380(zvol/vol2/zfs_backups/secure at 1243935776), -1, 
0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 
0xffffff000e832000(zvol/vol2/zfs_backups/secure at 1243935776)
Jul  5 19:42:50 host kernel: g_detach(0xffffff0035015380)
Jul  5 19:42:50 host kernel: 
g_access(0xffffff0035015380(zvol/vol2/zfs_backups/secure), 1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff0004acc100(zvol/vol2/zfs_backups/secure)
Jul  5 19:42:50 host kernel: 
g_access(0xffffff0035015380(zvol/vol2/zfs_backups/secure), -1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 0xffffff0004acc100(zvol/vol2/zfs_backups/secure)
Jul  5 19:42:50 host kernel: g_detach(0xffffff0035015380)
Jul  5 19:42:50 host kernel: 
g_access(0xffffff0035015380(zvol/vol2/zfs_backups/scanned at 1267226353), 1, 
0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 
0xffffff000e1fde00(zvol/vol2/zfs_backups/scanned at 1267226353)
Jul  5 19:42:50 host kernel: 
g_access(0xffffff0035015380(zvol/vol2/zfs_backups/scanned at 1267226353), -1, 
0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 
0xffffff000e1fde00(zvol/vol2/zfs_backups/scanned at 1267226353)
Jul  5 19:42:50 host kernel: g_detach(0xffffff0035015380)
Jul  5 19:42:50 host kernel: 
g_access(0xffffff0035015380(zvol/vol2/zfs_backups/scanned), 1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff000e1fd000(zvol/vol2/zfs_backups/scanned)
Jul  5 19:42:50 host kernel: 
g_access(0xffffff0035015380(zvol/vol2/zfs_backups/scanned), -1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r-1w0e0] old:[r1w0e0] 
provider:[r1w0e0] 0xffffff000e1fd000(zvol/vol2/zfs_backups/scanned)
Jul  5 19:42:50 host kernel: g_detach(0xffffff0035015380)
Jul  5 19:42:50 host kernel: 
g_access(0xffffff0035015380(zvol/vol/scanned at 1237495449), 1, 0, 0)
Jul  5 19:42:50 host kernel: open delta:[r1w0e0] old:[r0w0e0] 
provider:[r0w0e0] 0xffffff000e60b300(zvol/vol/scanned at 1237495449)
[hangs here]


More information about the freebsd-fs mailing list