Illumos #3618 ::zio dcmd does not show timestamp data

3618 ::zio dcmd does not show timestamp data
Reviewed by: Adam Leventhal <ahl@delphix.com>
Reviewed by: George Wilson <gwilson@zfsmail.com>
Reviewed by: Christopher Siden <christopher.siden@delphix.com>
Reviewed by: Garrett D'Amore <garrett@damore.org>
Approved by: Dan McDonald <danmcd@nexenta.com>

References:
  http://www.illumos.org/issues/3618
  illumos/illumos-gate@c55e05cb35da47582b7afd38734d2f0d9c6deb40

Notes on porting to ZFS on Linux:

The original changeset mostly deals with mdb ::zio dcmd.
However, in order to provide the requested functionality
it modifies vdev and zio structures to keep the timing data
in nanoseconds instead of ticks. It is these changes that
are ported over in the commit in hand.

One visible change of this commit is that the default value
of 'zfs_vdev_time_shift' tunable is changed:

    zfs_vdev_time_shift = 6
        to
    zfs_vdev_time_shift = 29

The original value of 6 was inherited from OpenSolaris and
was subotimal - since it shifted the raw tick value - it
didn't compensate for different tick frequencies on Linux and
OpenSolaris. The former has HZ=1000, while the latter HZ=100.

(Which itself led to other interesting performance anomalies
under non-trivial load. The deadline scheduler delays the IO
according to its priority - the lower priority the further
the deadline is set. The delay is measured in units of
"shifted ticks". Since the HZ value was 10 times higher,
the delay units were 10 times shorter. Thus really low
priority IO like resilver (delay is 10 units) and scrub
(delay is 20 units) were scheduled much sooner than intended.
The overall effect is that resilver and scrub IO consumed
more bandwidth at the expense of the other IO.)

Now that the bookkeeping is done is nanoseconds the shift
behaves correctly for any tick frequency (HZ).

Ported-by: Cyril Plisko <cyril.plisko@mountall.com>
Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
Closes #1643

diff --git a/include/sys/vdev_impl.h b/include/sys/vdev_impl.h
index 711408e6a9a399cac3f395647c49f674e1533259..e0669cc0b81becc571c1846d7fc3ffd89e44ea59 100644 (file)
--- a/include/sys/vdev_impl.h
+++ b/include/sys/vdev_impl.h
@@ -105,8 +105,8 @@ struct vdev_queue {
        avl_tree_t      vq_read_tree;
        avl_tree_t      vq_write_tree;
        avl_tree_t      vq_pending_tree;
-       uint64_t        vq_io_complete_ts;
-       uint64_t        vq_io_delta_ts;
+       hrtime_t        vq_io_complete_ts;
+       hrtime_t        vq_io_delta_ts;
        list_t          vq_io_list;
        kmutex_t        vq_lock;
 };

diff --git a/include/sys/zio.h b/include/sys/zio.h
index 03530330c95f0a404e357726b7ca2aba1533b5ce..189966bef54c4ed5a2a9fdf931e53e90737807fc 100644 (file)
--- a/include/sys/zio.h
+++ b/include/sys/zio.h
@@ -410,8 +410,8 @@ struct zio {
 
        uint64_t        io_offset;
        uint64_t        io_deadline;    /* expires at timestamp + deadline */
-       uint64_t        io_timestamp;   /* submitted at (ticks) */
-       uint64_t        io_delta;       /* vdev queue service delta (ticks) */
+       hrtime_t        io_timestamp;   /* submitted at */
+       hrtime_t        io_delta;       /* vdev queue service delta */
        uint64_t        io_delay;       /* vdev disk service delta (ticks) */
        avl_node_t      io_offset_node;
        avl_node_t      io_deadline_node;

diff --git a/module/zfs/vdev.c b/module/zfs/vdev.c
index d6b55ee48f4d65a315e583596c33df70fe0219e5..662a877f8543a09d15a3bfa1e25b8de822f2a4c8 100644 (file)
--- a/module/zfs/vdev.c
+++ b/module/zfs/vdev.c
@@ -3219,10 +3219,10 @@ vdev_deadman(vdev_t *vd)
                         * the spa_deadman_synctime we log a zevent.
                         */
                        fio = avl_first(&vq->vq_pending_tree);
-                       delta = ddi_get_lbolt64() - fio->io_timestamp;
-                       if (delta > NSEC_TO_TICK(spa_deadman_synctime(spa))) {
-                               zfs_dbgmsg("SLOW IO: zio timestamp %llu, "
-                                   "delta %llu, last io %llu",
+                       delta = gethrtime() - fio->io_timestamp;
+                       if (delta > spa_deadman_synctime(spa)) {
+                               zfs_dbgmsg("SLOW IO: zio timestamp %lluns, "
+                                   "delta %lluns, last io %lluns",
                                    fio->io_timestamp, delta,
                                    vq->vq_io_complete_ts);
                                zfs_ereport_post(FM_EREPORT_ZFS_DELAY,

diff --git a/module/zfs/vdev_queue.c b/module/zfs/vdev_queue.c
index 3f2793ba4f1623f7e1c0374c0a5ffd73295b8360..b2cc6b87ffd783ea927a563f308729c59ffc0ab0 100644 (file)
--- a/module/zfs/vdev_queue.c
+++ b/module/zfs/vdev_queue.c
@@ -44,8 +44,11 @@
 int zfs_vdev_max_pending = 10;
 int zfs_vdev_min_pending = 4;
 
-/* deadline = pri + ddi_get_lbolt64() >> time_shift) */
-int zfs_vdev_time_shift = 6;
+/*
+ * The deadlines are grouped into buckets based on zfs_vdev_time_shift:
+ * deadline = pri + gethrtime() >> time_shift)
+ */
+int zfs_vdev_time_shift = 29; /* each bucket is 0.537 seconds */
 
 /* exponential I/O issue ramp-up rate */
 int zfs_vdev_ramp_rate = 2;
@@ -396,7 +399,7 @@ vdev_queue_io(zio_t *zio)
 
        mutex_enter(&vq->vq_lock);
 
-       zio->io_timestamp = ddi_get_lbolt64();
+       zio->io_timestamp = gethrtime();
        zio->io_deadline = (zio->io_timestamp >> zfs_vdev_time_shift) +
            zio->io_priority;
 
@@ -430,8 +433,8 @@ vdev_queue_io_done(zio_t *zio)
 
        avl_remove(&vq->vq_pending_tree, zio);
 
-       zio->io_delta = ddi_get_lbolt64() - zio->io_timestamp;
-       vq->vq_io_complete_ts = ddi_get_lbolt64();
+       zio->io_delta = gethrtime() - zio->io_timestamp;
+       vq->vq_io_complete_ts = gethrtime();
        vq->vq_io_delta_ts = vq->vq_io_complete_ts - zio->io_timestamp;
 
        for (i = 0; i < zfs_vdev_ramp_rate; i++) {