Add visibility in to dmu_tx_assign times

This change adds a new kstat to gain some visibility into the
amount of time spent in each call to dmu_tx_assign. A histogram
is exported via the new dmu_tx_assign file. The information
contained in this histogram is the frequency dmu_tx_assign
took to complete given an interval range.

Signed-off-by: Prakash Surya <surya1@llnl.gov>
Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>

diff --git a/include/sys/spa.h b/include/sys/spa.h
index 85a62588aedd38ef198ebc01e8f67211e2f55ff2..cb3ce11bca6d7ff0be82b3dd77dacade603518a4 100644 (file)
--- a/include/sys/spa.h
+++ b/include/sys/spa.h
@@ -549,6 +549,7 @@ typedef struct spa_stats_history {
 typedef struct spa_stats {
        spa_stats_history_t     read_history;
        spa_stats_history_t     txg_history;
+       spa_stats_history_t     tx_assign_histogram;
 } spa_stats_t;
 
 typedef enum txg_state {
@@ -568,6 +569,7 @@ extern int spa_txg_history_set(spa_t *spa,  uint64_t txg,
     txg_state_t completed_state, hrtime_t completed_time);
 extern int spa_txg_history_set_io(spa_t *spa,  uint64_t txg, uint64_t nread,
     uint64_t nwritten, uint64_t reads, uint64_t writes, uint64_t nreserved);
+extern void spa_tx_assign_add_nsecs(spa_t *spa, uint64_t nsecs);
 
 /* Pool configuration locks */
 extern int spa_config_tryenter(spa_t *spa, int locks, void *tag, krw_t rw);

diff --git a/module/zfs/dmu_tx.c b/module/zfs/dmu_tx.c
index 17982a04eca435a8926fba2029682574fef85b33..7b62239567f5d95b9550b92eb93593c511a88f04 100644 (file)
--- a/module/zfs/dmu_tx.c
+++ b/module/zfs/dmu_tx.c
@@ -1077,12 +1077,15 @@ dmu_tx_unassign(dmu_tx_t *tx)
 int
 dmu_tx_assign(dmu_tx_t *tx, txg_how_t txg_how)
 {
+       hrtime_t before;
        int err;
 
        ASSERT(tx->tx_txg == 0);
        ASSERT(txg_how == TXG_WAIT || txg_how == TXG_NOWAIT);
        ASSERT(!dsl_pool_sync_context(tx->tx_pool));
 
+       before = gethrtime();
+
        /* If we might wait, we must not hold the config lock. */
        ASSERT(txg_how != TXG_WAIT || !dsl_pool_config_held(tx->tx_pool));
 
@@ -1097,6 +1100,8 @@ dmu_tx_assign(dmu_tx_t *tx, txg_how_t txg_how)
 
        txg_rele_to_quiesce(&tx->tx_txgh);
 
+       spa_tx_assign_add_nsecs(tx->tx_pool->dp_spa, gethrtime() - before);
+
        return (0);
 }
 

diff --git a/module/zfs/spa_stats.c b/module/zfs/spa_stats.c
index 16ccbb0ad53a40059e280d92e3e4168bfc6a275c..789e8c3e61b7763ea3c789c08706b46eb6ef3c2b 100644 (file)
--- a/module/zfs/spa_stats.c
+++ b/module/zfs/spa_stats.c
@@ -504,16 +504,122 @@ spa_txg_history_set_io(spa_t *spa, uint64_t txg, uint64_t nread,
        return (error);
 }
 
+/*
+ * ==========================================================================
+ * SPA TX Assign Histogram Routines
+ * ==========================================================================
+ */
+
+/*
+ * Tx statistics - Information exported regarding dmu_tx_assign time.
+ */
+
+/*
+ * When the kstat is written zero all buckets.  When the kstat is read
+ * count the number of trailing buckets set to zero and update ks_ndata
+ * such that they are not output.
+ */
+static int
+spa_tx_assign_update(kstat_t *ksp, int rw)
+{
+       spa_t *spa = ksp->ks_private;
+       spa_stats_history_t *ssh = &spa->spa_stats.tx_assign_histogram;
+       int i;
+
+       if (rw == KSTAT_WRITE) {
+               for (i = 0; i < ssh->count; i++)
+                       ((kstat_named_t *)ssh->private)[i].value.ui64 = 0;
+       }
+
+       for (i = ssh->count; i > 0; i--)
+               if (((kstat_named_t *)ssh->private)[i-1].value.ui64 != 0)
+                       break;
+
+       ksp->ks_ndata = i;
+       ksp->ks_data_size = i * sizeof(kstat_named_t);
+
+       return (0);
+}
+
+static void
+spa_tx_assign_init(spa_t *spa)
+{
+       spa_stats_history_t *ssh = &spa->spa_stats.tx_assign_histogram;
+       char name[KSTAT_STRLEN];
+       kstat_named_t *ks;
+       kstat_t *ksp;
+       int i;
+
+       mutex_init(&ssh->lock, NULL, MUTEX_DEFAULT, NULL);
+
+       ssh->count = 42; /* power of two buckets for 1ns to 2,199s */
+       ssh->size = ssh->count * sizeof(kstat_named_t);
+       ssh->private = kmem_alloc(ssh->size, KM_SLEEP);
+
+       (void) snprintf(name, KSTAT_STRLEN, "zfs/%s", spa_name(spa));
+       name[KSTAT_STRLEN-1] = '\0';
+
+       for (i = 0; i < ssh->count; i++) {
+               ks = &((kstat_named_t *)ssh->private)[i];
+               ks->data_type = KSTAT_DATA_UINT64;
+               ks->value.ui64 = 0;
+               (void) snprintf(ks->name, KSTAT_STRLEN, "%llu ns",
+                   (u_longlong_t)1 << i);
+       }
+
+       ksp = kstat_create(name, 0, "dmu_tx_assign", "misc",
+           KSTAT_TYPE_NAMED, 0, KSTAT_FLAG_VIRTUAL);
+       ssh->kstat = ksp;
+
+       if (ksp) {
+               ksp->ks_lock = &ssh->lock;
+               ksp->ks_data = ssh->private;
+               ksp->ks_ndata = ssh->count;
+               ksp->ks_data_size = ssh->size;
+               ksp->ks_private = spa;
+               ksp->ks_update = spa_tx_assign_update;
+               kstat_install(ksp);
+       }
+}
+
+static void
+spa_tx_assign_destroy(spa_t *spa)
+{
+       spa_stats_history_t *ssh = &spa->spa_stats.tx_assign_histogram;
+       kstat_t *ksp;
+
+       ksp = ssh->kstat;
+       if (ksp)
+               kstat_delete(ksp);
+
+       kmem_free(ssh->private, ssh->size);
+       mutex_destroy(&ssh->lock);
+}
+
+void
+spa_tx_assign_add_nsecs(spa_t *spa, uint64_t nsecs)
+{
+       spa_stats_history_t *ssh = &spa->spa_stats.tx_assign_histogram;
+       uint64_t idx = 0;
+
+       while (((1 << idx) < nsecs) && (idx < ssh->size - 1))
+               idx++;
+
+       atomic_inc_64(&((kstat_named_t *)ssh->private)[idx].value.ui64);
+}
+
 void
 spa_stats_init(spa_t *spa)
 {
        spa_read_history_init(spa);
        spa_txg_history_init(spa);
+       spa_tx_assign_init(spa);
 }
 
 void
 spa_stats_destroy(spa_t *spa)
 {
+       spa_tx_assign_destroy(spa);
        spa_txg_history_destroy(spa);
        spa_read_history_destroy(spa);
 }