regarding output from fmdump -e

Discussion:

Dennis Clarke

2009-05-28 19:18:54 UTC

I notice that the timestamps on the output from fmdump -e were not
chronological.

thus :

Mar 23 23:47:28.5619 ereport.fs.zfs.io
Mar 23 23:47:28.5615 ereport.fs.zfs.io
Mar 23 23:47:28.5618 ereport.fs.zfs.io
Mar 23 23:47:28.5645 ereport.fs.zfs.io
Mar 23 23:47:28.5652 ereport.fs.zfs.io
Mar 23 23:47:28.5610 ereport.fs.zfs.io
Mar 23 23:48:41.5944 ereport.fs.zfs.io
Mar 23 23:47:28.5649 ereport.fs.zfs.io
Mar 23 23:47:28.5623 ereport.fs.zfs.io
Mar 23 23:48:41.5945 ereport.fs.zfs.io
Mar 23 23:47:28.5654 ereport.fs.zfs.io
Mar 23 23:47:28.5628 ereport.fs.zfs.io
Mar 23 23:47:28.5615 ereport.fs.zfs.io
Mar 23 23:47:28.5624 ereport.fs.zfs.io
Mar 23 23:47:28.5615 ereport.fs.zfs.io
Mar 23 23:47:28.5579 ereport.fs.zfs.io
Mar 23 23:47:28.5559 ereport.fs.zfs.io
Mar 23 23:47:28.5616 ereport.fs.zfs.io
Mar 23 23:47:28.5656 ereport.fs.zfs.io
Mar 23 23:47:28.5643 ereport.fs.zfs.io
Mar 23 23:47:28.5551 ereport.fs.zfs.io
Mar 23 23:47:28.5630 ereport.fs.zfs.io
Mar 23 23:47:28.5557 ereport.fs.zfs.io
Mar 23 23:47:28.5582 ereport.fs.zfs.io
Mar 23 23:47:28.5622 ereport.fs.zfs.io
Mar 23 23:47:28.5560 ereport.fs.zfs.io
Mar 23 23:47:28.5658 ereport.fs.zfs.io
Mar 23 23:48:41.5957 ereport.fs.zfs.io

Is this out-of-order list intended ?

--
Dennis Clarke

Daniel Ellison

2009-06-01 23:01:04 UTC

Permalink

Dennis,

Not sure what sort of platform this is; however, to me it looks like
this system was trying to recover from many IO errors at once. Some of
them may have gotten processed ahead of others. Depending on the
architecture and the load at the time of the IO errors I could think of
a few reasons why that might have happened. In order to further
investigate why that might have been I'd file a service request and
upload some explorer data for analysis.

Hope this help!

Rgds.
Daniel Ellison
Staff Engineer
Technology Service Center
Sun Microsystems, Inc.

Post by Dennis Clarke
I notice that the timestamps on the output from fmdump -e were not
chronological.
Mar 23 23:47:28.5619 ereport.fs.zfs.io
Mar 23 23:47:28.5615 ereport.fs.zfs.io
Mar 23 23:47:28.5618 ereport.fs.zfs.io
Mar 23 23:47:28.5645 ereport.fs.zfs.io
Mar 23 23:47:28.5652 ereport.fs.zfs.io
Mar 23 23:47:28.5610 ereport.fs.zfs.io
Mar 23 23:48:41.5944 ereport.fs.zfs.io
Mar 23 23:47:28.5649 ereport.fs.zfs.io
Mar 23 23:47:28.5623 ereport.fs.zfs.io
Mar 23 23:48:41.5945 ereport.fs.zfs.io
Mar 23 23:47:28.5654 ereport.fs.zfs.io
Mar 23 23:47:28.5628 ereport.fs.zfs.io
Mar 23 23:47:28.5615 ereport.fs.zfs.io
Mar 23 23:47:28.5624 ereport.fs.zfs.io
Mar 23 23:47:28.5615 ereport.fs.zfs.io
Mar 23 23:47:28.5579 ereport.fs.zfs.io
Mar 23 23:47:28.5559 ereport.fs.zfs.io
Mar 23 23:47:28.5616 ereport.fs.zfs.io
Mar 23 23:47:28.5656 ereport.fs.zfs.io
Mar 23 23:47:28.5643 ereport.fs.zfs.io
Mar 23 23:47:28.5551 ereport.fs.zfs.io
Mar 23 23:47:28.5630 ereport.fs.zfs.io
Mar 23 23:47:28.5557 ereport.fs.zfs.io
Mar 23 23:47:28.5582 ereport.fs.zfs.io
Mar 23 23:47:28.5622 ereport.fs.zfs.io
Mar 23 23:47:28.5560 ereport.fs.zfs.io
Mar 23 23:47:28.5658 ereport.fs.zfs.io
Mar 23 23:48:41.5957 ereport.fs.zfs.io
Is this out-of-order list intended ?

Gavin Maltby

2009-06-01 23:36:11 UTC

Permalink

Hi,

The way most ereport generation code is structure makes it a
little tricky to see what point(s) in the source generate
a particular ereport - the class is usually pieced together
and you can't search for that string using cscope or whatever.

A strategy that usually works is to look in uts/common/sys/fm
for components of the ereport class. Looking for string "zfs"
in the files there we find fs/zfs.h:

#define ZFS_ERROR_CLASS "fs.zfs"

and moments later we find the leaf class

#define FM_EREPORT_ZFS_IO "io"

So searching for FM_EREPORT_ZFS_IO in cscope we find the
definition above, 3 uses in the diagnosis engine, and
a use in zio_done in zio.c - this last one is where the
ereport is generated:

if (zio->io_error) {
/*
* If this I/O is attached to a particular vdev,
* generate an error message describing the I/O failure
* at the block level. We ignore these errors if the
* device is currently unavailable.
*/
if (zio->io_error != ECKSUM && vd != NULL && !vdev_is_dead(vd))
zfs_ereport_post(FM_EREPORT_ZFS_IO, spa, vd, zio, 0, 0);

zfs_ereport_post has the uneviable job of trying to correlate some of the
error observations. The "ena" member of the ereport includes a
component of hrtime and a generation number for the event number
in a sequence of related events. There's a giant comment above
zfs_ereport_post describing how it tries to track/assign ena
to ereports surfacing from the different layer so that
we can identify some of them as being a chain of events.

So ereports are being posted in the order this function is called, but
with ena values that effectively adjust the event time as seen in
fmdump output. The errlog is always appended in order of event
receipt (received events are synchronously written to it before
being acked to the kernel, and replayed from the errlog at fmd
startup if they're not marked as consumed by a diagnosis engine).
Internally fmd inserts received events in time order in the
dispatch queues to subscribing modules, although that only
gives you a localized time order - an event received a day
late won't manage to get ahead of others you've already delivered
for diagnosis.

Unless the zfs stuff is misdiagnosing something I'd assume it
got it all right below - if it is misdiagnosing then perhaps
the event order and the complex ena juggling in zfs_ereport_post
would be the first place to start.

Cheers

Gavin

Post by Daniel Ellison
Dennis,
Not sure what sort of platform this is; however, to me it looks like
this system was trying to recover from many IO errors at once. Some of
them may have gotten processed ahead of others. Depending on the
architecture and the load at the time of the IO errors I could think of
a few reasons why that might have happened. In order to further
investigate why that might have been I'd file a service request and
upload some explorer data for analysis.
Hope this help!
Rgds.
Daniel Ellison
Staff Engineer
Technology Service Center
Sun Microsystems, Inc.

_______________________________________________
fm-discuss mailing list