From 2d37239a28b8b2ddc0e8312093f8d8810c6351fa Mon Sep 17 00:00:00 2001 From: Brian Behlendorf Date: Wed, 2 Oct 2013 11:43:52 -0700 Subject: [PATCH] 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 Signed-off-by: Brian Behlendorf --- include/sys/spa.h | 2 + module/zfs/dmu_tx.c | 5 ++ module/zfs/spa_stats.c | 106 +++++++++++++++++++++++++++++++++++++++++ 3 files changed, 113 insertions(+) diff --git a/include/sys/spa.h b/include/sys/spa.h index 85a62588ae..cb3ce11bca 100644 --- 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 17982a04ec..7b62239567 100644 --- 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 16ccbb0ad5..789e8c3e61 100644 --- 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); }